18:20:24.389[app:dbg]MATCH: fulldialed 0, can`t dial more 0, dialtone 0 fullmatch 0
18:20:24.389[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:20:24.389[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:20:24.389[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:20:24.389[app:dbg]check item 1: 0x03FF/00000000,0 : <1>
18:20:24.389[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:20:24.389[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:20:24.389[app:dbg]check item 2: 0x03FF/00000000,0 : <F>
18:20:24.389[app:dbg]check 'cant dial more' within cycle: item 1, crt 0, {0,0}
18:20:24.389[app:dbg]MATCH: fulldialed 0, can`t dial more 0, dialtone 0 fullmatch 0
18:20:24.389[app:dbg]check item 0: 0x03FF/080000FF,0 : <1>
18:20:24.389[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 0, digit '1' mask 0x3FF
18:20:24.389[app:dbg]<cur match>: dial <1>r 1, dt 0, sub 0 r{0,255(inf)}
18:20:24.389[app:dbg]match ok: rf 0, crt 1, rt 255
18:20:24.389[app:dbg]check item 0: 0x03FF/080000FF,1 : <1>
18:20:24.389[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 1, digit '1' mask 0x3FF
18:20:24.389[app:dbg]<cur match>: dial <1>r 2, dt 0, sub 0 r{0,255(inf)}
18:20:24.389[app:dbg]match ok: rf 0, crt 2, rt 255
18:20:24.389[app:dbg]end of items - test dial ended
18:20:24.389[app:dbg]check 'cant dial more' out of the cycle: item 0, crt 2, r{0,255(inf)}
18:20:24.389[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 1
18:20:24.389[app:dbg]check item 0: 0x0FFF/080000FF,0 : <1>
18:20:24.389[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 0, digit '1' mask 0xFFF
18:20:24.389[app:dbg]<cur match>: dial <1>r 1, dt 0, sub 0 r{0,255(inf)}
18:20:24.389[app:dbg]match ok: rf 0, crt 1, rt 255
18:20:24.389[app:dbg]check item 0: 0x0FFF/080000FF,1 : <1>
18:20:24.389[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 1, digit '1' mask 0xFFF
18:20:24.389[app:dbg]<cur match>: dial <1>r 2, dt 0, sub 0 r{0,255(inf)}
18:20:24.389[app:dbg]match ok: rf 0, crt 2, rt 255
18:20:24.389[app:dbg]end of items - test dial ended
18:20:24.389[app:dbg]check 'cant dial more' out of the cycle: item 0, crt 2, r{0,255(inf)}
18:20:24.389[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 1
18:20:24.389[app:dbg]04: [3,4,5,10,11,]
18:20:24.389[app:dbg]port_process_digit() regex route 0x304408, final 1, dt 0
18:20:24.389[app:dbg]port 4: process final route
18:20:24.519[app:dbg]vapi_proc_event: eVAPI_TONE_DETECT_EVENT
18:20:24.519[app:dbg]vapi: tone detect: Conn 4. End of signal <DTMF digit 1>, duration 160 ms
18:20:25.039[app:dbg]port 4: regex per sec timeout
18:20:25.489[app:dbg]vapi_proc_event: eVAPI_TONE_DETECT_EVENT
18:20:25.489[app:dbg]vapi: tone detect: Conn 4. Detect signal <DTMF digit 0> (level 7 dBov)
18:20:25.499[app:dbg]hio: port 4: digit 0 (code 0x10), tone
18:20:25.499[app:dbg]no matched dvo for 110
18:20:25.499[app:info]SLIC 4: digit 0
18:20:25.499[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:20:25.499[app:dbg]regex_match_item: check route 0x304408 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:20:25.499[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:20:25.499[app:dbg]check item 1: 0x03FF/00000000,0 : <1>
18:20:25.499[app:dbg]regex_match_item: check route 0x304408 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:20:25.499[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:20:25.499[app:dbg]end of items - test dial ended
18:20:25.499[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:20:25.499[app:dbg]regex_match_item: check route 0x304560 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:20:25.499[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:20:25.499[app:dbg]check item 1: 0x03FF/00000000,0 : <1>
18:20:25.499[app:dbg]regex_match_item: check route 0x304560 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:20:25.499[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:20:25.499[app:dbg]check item 2: 0x03FF/00000000,0 : <0>
18:20:25.499[app:dbg]regex_match_item: check route 0x304560 repeat off rf 0, rt 0, crt 0, digit '0' mask 0x3FF
18:20:25.499[app:dbg]<cur match>: dial <0>r 0, dt 0, sub 0 {0,0}
18:20:25.499[app:dbg]end of items - test dial ended
18:20:25.499[app:dbg]check 'cant dial more' out of the cycle: item 2, crt 0, {0,0}
18:20:25.499[app:dbg]MATCH: fulldialed 1, can`t dial more 1, dialtone 0 fullmatch 1
18:20:25.499[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:20:25.499[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:20:25.499[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:20:25.499[app:dbg]check item 1: 0x03FF/00000000,0 : <1>
18:20:25.499[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:20:25.499[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:20:25.499[app:dbg]check item 2: 0x03FF/00000000,0 : <0>
18:20:25.499[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '0' mask 0x3FF
18:20:25.499[app:dbg]<cur match>: dial <0>r 0, dt 0, sub 0 {0,0}
18:20:25.499[app:dbg]check item 3: 0x03FF/080000FF,0 : <F>
18:20:25.499[app:dbg]check 'cant dial more' within cycle: item 2, crt 0, {0,0}
18:20:25.499[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 0
18:20:25.499[app:dbg]check item 0: 0x03FF/080000FF,0 : <1>
18:20:25.499[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 0, digit '1' mask 0x3FF
18:20:25.499[app:dbg]<cur match>: dial <1>r 1, dt 0, sub 0 r{0,255(inf)}
18:20:25.499[app:dbg]match ok: rf 0, crt 1, rt 255
18:20:25.499[app:dbg]check item 0: 0x03FF/080000FF,1 : <1>
18:20:25.499[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 1, digit '1' mask 0x3FF
18:20:25.499[app:dbg]<cur match>: dial <1>r 2, dt 0, sub 0 r{0,255(inf)}
18:20:25.499[app:dbg]match ok: rf 0, crt 2, rt 255
18:20:25.499[app:dbg]check item 0: 0x03FF/080000FF,2 : <0>
18:20:25.499[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 2, digit '0' mask 0x3FF
18:20:25.499[app:dbg]<cur match>: dial <0>r 3, dt 0, sub 0 r{0,255(inf)}
18:20:25.499[app:dbg]match ok: rf 0, crt 3, rt 255
18:20:25.499[app:dbg]end of items - test dial ended
18:20:25.499[app:dbg]check 'cant dial more' out of the cycle: item 0, crt 3, r{0,255(inf)}
18:20:25.499[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 1
18:20:25.499[app:dbg]check item 0: 0x0FFF/080000FF,0 : <1>
18:20:25.499[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 0, digit '1' mask 0xFFF
18:20:25.499[app:dbg]<cur match>: dial <1>r 1, dt 0, sub 0 r{0,255(inf)}
18:20:25.499[app:dbg]match ok: rf 0, crt 1, rt 255
18:20:25.499[app:dbg]check item 0: 0x0FFF/080000FF,1 : <1>
18:20:25.499[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 1, digit '1' mask 0xFFF
18:20:25.499[app:dbg]<cur match>: dial <1>r 2, dt 0, sub 0 r{0,255(inf)}
18:20:25.499[app:dbg]match ok: rf 0, crt 2, rt 255
18:20:25.499[app:dbg]check item 0: 0x0FFF/080000FF,2 : <0>
18:20:25.499[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 2, digit '0' mask 0xFFF
18:20:25.499[app:dbg]<cur match>: dial <0>r 3, dt 0, sub 0 r{0,255(inf)}
18:20:25.499[app:dbg]match ok: rf 0, crt 3, rt 255
18:20:25.499[app:dbg]end of items - test dial ended
18:20:25.499[app:dbg]check 'cant dial more' out of the cycle: item 0, crt 3, r{0,255(inf)}
18:20:25.499[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 1
18:20:25.499[app:dbg]04: [4,5,10,11,]
18:20:25.499[app:dbg]port_process_digit() regex route 0x304560, final 1, dt 0
18:20:25.499[app:dbg]port 4: process final route
18:20:25.579[app:dbg]vapi_proc_event: eVAPI_TONE_DETECT_EVENT
18:20:25.579[app:dbg]vapi: tone detect: Conn 4. End of signal <DTMF digit 0>, duration 100 ms
18:20:25.959[app:dbg]vapi_proc_event: eVAPI_TONE_DETECT_EVENT
18:20:25.959[app:dbg]vapi: tone detect: Conn 4. Detect signal <DTMF digit 1> (level 6 dBov)
18:20:25.969[app:dbg]hio: port 4: digit 1 (code 0x11), tone
18:20:25.969[app:dbg]no matched dvo for 1101
18:20:25.969[app:info]SLIC 4: digit 1
18:20:25.969[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:20:25.969[app:dbg]regex_match_item: check route 0x304560 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:20:25.969[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:20:25.969[app:dbg]check item 1: 0x03FF/00000000,0 : <1>
18:20:25.969[app:dbg]regex_match_item: check route 0x304560 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:20:25.969[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:20:25.969[app:dbg]check item 2: 0x03FF/00000000,0 : <0>
18:20:25.969[app:dbg]regex_match_item: check route 0x304560 repeat off rf 0, rt 0, crt 0, digit '0' mask 0x3FF
18:20:25.969[app:dbg]<cur match>: dial <0>r 0, dt 0, sub 0 {0,0}
18:20:25.969[app:dbg]end of items - test dial ended
18:20:25.969[app:dbg]check item 0: 0x03FF/00000000,0 : <1>
18:20:25.969[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:20:25.969[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:20:25.969[app:dbg]check item 1: 0x03FF/00000000,0 : <1>
18:20:25.969[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '1' mask 0x3FF
18:20:25.969[app:dbg]<cur match>: dial <1>r 0, dt 0, sub 0 {0,0}
18:20:25.969[app:dbg]check item 2: 0x03FF/00000000,0 : <0>
18:20:25.969[app:dbg]regex_match_item: check route 0x3046b8 repeat off rf 0, rt 0, crt 0, digit '0' mask 0x3FF
18:20:25.969[app:dbg]<cur match>: dial <0>r 0, dt 0, sub 0 {0,0}
18:20:25.969[app:dbg]check item 3: 0x03FF/080000FF,0 : <1>
18:20:25.969[app:dbg]regex_match_item: check route 0x3046b8 repeat on rf 0, rt 255(inf), crt 0, digit '1' mask 0x3FF
18:20:25.969[app:dbg]<cur match>: dial <1>r 1, dt 0, sub 0 r{0,255(inf)}
18:20:25.969[app:dbg]match ok: rf 0, crt 1, rt 255
18:20:25.969[app:dbg]end of items - test dial ended
18:20:25.969[app:dbg]check 'cant dial more' out of the cycle: item 3, crt 1, r{0,255(inf)}
18:20:25.969[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 1
18:20:25.969[app:dbg]check item 0: 0x03FF/080000FF,0 : <1>
18:20:25.969[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 0, digit '1' mask 0x3FF
18:20:25.969[app:dbg]<cur match>: dial <1>r 1, dt 0, sub 0 r{0,255(inf)}
18:20:25.969[app:dbg]match ok: rf 0, crt 1, rt 255
18:20:25.969[app:dbg]check item 0: 0x03FF/080000FF,1 : <1>
18:20:25.969[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 1, digit '1' mask 0x3FF
18:20:25.969[app:dbg]<cur match>: dial <1>r 2, dt 0, sub 0 r{0,255(inf)}
18:20:25.969[app:dbg]match ok: rf 0, crt 2, rt 255
18:20:25.969[app:dbg]check item 0: 0x03FF/080000FF,2 : <0>
18:20:25.969[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 2, digit '0' mask 0x3FF
18:20:25.969[app:dbg]<cur match>: dial <0>r 3, dt 0, sub 0 r{0,255(inf)}
18:20:25.969[app:dbg]match ok: rf 0, crt 3, rt 255
18:20:25.969[app:dbg]check item 0: 0x03FF/080000FF,3 : <1>
18:20:25.969[app:dbg]regex_match_item: check route 0x304d70 repeat on rf 0, rt 255(inf), crt 3, digit '1' mask 0x3FF
18:20:25.969[app:dbg]<cur match>: dial <1>r 4, dt 0, sub 0 r{0,255(inf)}
18:20:25.969[app:dbg]match ok: rf 0, crt 4, rt 255
18:20:25.969[app:dbg]end of items - test dial ended
18:20:25.969[app:dbg]check 'cant dial more' out of the cycle: item 0, crt 4, r{0,255(inf)}
18:20:25.969[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 1
18:20:25.969[app:dbg]check item 0: 0x0FFF/080000FF,0 : <1>
18:20:25.969[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 0, digit '1' mask 0xFFF
18:20:25.969[app:dbg]<cur match>: dial <1>r 1, dt 0, sub 0 r{0,255(inf)}
18:20:25.969[app:dbg]match ok: rf 0, crt 1, rt 255
18:20:25.969[app:dbg]check item 0: 0x0FFF/080000FF,1 : <1>
18:20:25.969[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 1, digit '1' mask 0xFFF
18:20:25.969[app:dbg]<cur match>: dial <1>r 2, dt 0, sub 0 r{0,255(inf)}
18:20:25.969[app:dbg]match ok: rf 0, crt 2, rt 255
18:20:25.969[app:dbg]check item 0: 0x0FFF/080000FF,2 : <0>
18:20:25.969[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 2, digit '0' mask 0xFFF
18:20:25.969[app:dbg]<cur match>: dial <0>r 3, dt 0, sub 0 r{0,255(inf)}
18:20:25.969[app:dbg]match ok: rf 0, crt 3, rt 255
18:20:25.969[app:dbg]check item 0: 0x0FFF/080000FF,3 : <1>
18:20:25.969[app:dbg]regex_match_item: check route 0x304ec8 repeat on rf 0, rt 255(inf), crt 3, digit '1' mask 0xFFF
18:20:25.969[app:dbg]<cur match>: dial <1>r 4, dt 0, sub 0 r{0,255(inf)}
18:20:25.969[app:dbg]match ok: rf 0, crt 4, rt 255
18:20:25.969[app:dbg]end of items - test dial ended
18:20:25.969[app:dbg]check 'cant dial more' out of the cycle: item 0, crt 4, r{0,255(inf)}
18:20:25.969[app:dbg]MATCH: fulldialed 1, can`t dial more 0, dialtone 0 fullmatch 1
18:20:25.969[app:dbg]04: [5,10,11,]
18:20:25.969[app:dbg]port_process_digit() regex route 0x3046b8, final 1, dt 0
18:20:25.969[app:dbg]port 4: process final route
18:20:26.039[app:dbg]port 4: regex per sec timeout
18:20:26.069[app:dbg]vapi_proc_event: eVAPI_TONE_DETECT_EVENT
18:20:26.069[app:dbg]vapi: tone detect: Conn 4. End of signal <DTMF digit 1>, duration 100 ms
18:20:27.039[app:dbg]port 4: regex per sec timeout
18:20:28.029[app:dbg]port 4: regex per sec timeout
18:20:29.019[app:dbg]port 4: regex per sec timeout
18:20:30.039[app:dbg]port 4: regex per sec timeout
18:20:30.039[app:dbg]SLIC 4: final action
18:20:30.039[app:info]SLIC 4: dial <1101>
18:20:30.039[app:dbg]pbx: allocating memory for new call
18:20:30.039[app:dbg]pbx: created new outgoing call for SLIC 4
18:20:30.039[app:dbg]self_call_create (4455): created
18:20:30.039[app:dbg]free_final_mx: final_mx was NULL for SLIC 4
18:20:30.039[app:dbg]SLIC 4: -> calling to sip//1101
18:20:30.039[app:dbg]ext: 0
18:20:30.039[app:dbg]pbx -[msg_call]-> sip
18:20:30.039[app:info]SLIC 4: from state 'dial' to state 'calling'
18:20:30.039[app:dbg]CMD_STOP_TONE: port = 4
18:20:30.039[app:dbg]Port 4: check vapi queue ('free') at vapi_stop_tone_chan:1474
18:20:30.039[app:dbg]Chan 4: current state is CREATED
18:20:30.039[app:ERR]chan 4: no generated tones!
18:20:30.039[app:dbg]vapi_chan.c:1510: conn 4 peek cmd 'no event' from queue
18:20:30.039[app:dbg]Port 4: check vapi queue ('free') at __cmd_engine:320
18:20:30.039[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2532
18:20:30.039[app:dbg]Port 4: user port 2, old state calling, new state
18:20:30.039[app:dbg]Set port 4 led to state 'LED_ON'
18:20:30.039[app:dbg]pbx -[msg_fxs_state]-> group
18:20:30.039[app:dbg]ITC: [msg_call] -> sip
18:20:30.039[app:dbg]sip: outgoing call 00040019 from endpoint 4 to 1101@(null)
18:20:30.039[app:dbg]available RTP ports: 23000...26000
18:20:30.039[app:dbg]selected port for current call: 23448
18:20:30.039[app:dbg]sip_params_create() normal - using cur proxy [192.168.100.90] if proxy call
18:20:30.039[app:dbg]stun_get_public_ip(port = 8000)
18:20:30.039[app:dbg]stun_get_public_ip: Always using local IP
18:20:30.039[app:dbg]sip: to host is <(null)> - should not have port; to user is <1101>, use proxy - yes
18:20:30.039[app:dbg]sip_params_create() send to is <sip:1101@192.168.100.90>, <not outbound>
18:20:30.039[app:dbg]sip_params_create() target,request url is <sip:1101@192.168.100.90>
18:20:30.039[app:dbg]sip: call 00040019: sip  INVITE from sip:1102@192.168.100.90 to sip:1101@192.168.100.90
18:20:30.039[app:dbg]sip: call 00040019: targeturl is <sip:1101@192.168.100.90>
18:20:30.039[app:dbg]build contact field with To-Host '192.168.100.90'
18:20:30.039[app:dbg]stun_get_public_ip(port = 5060)
18:20:30.039[app:dbg]stun_get_public_ip: Always using local IP
18:20:30.039[app:dbg]stun_get_public_ip(port = 23448)
18:20:30.039[app:dbg]stun_get_public_ip: Always using local IP
18:20:30.039[app:dbg]sdp_codecs_init() init call sdp (offer)
18:20:30.039[app:dbg]sdp_codecs_dump() ssup present on, ecan absent on, rfc absent 101, nse absent 0, ptime present 20
18:20:30.039[app:dbg]sdp_codecs_dump() G723: none
18:20:30.039[app:dbg]sdp_codecs_dump() G711A:
18:20:30.039[app:dbg]sdp_codecs_dump() PT 8, vbd absent off
18:20:30.039[app:dbg]sdp_codecs_dump() G711U:
18:20:30.039[app:dbg]sdp_codecs_dump() PT 0, vbd absent off
18:20:30.039[app:dbg]sdp_codecs_g711a_add_to_media_attrs() g711a: have one at last
18:20:30.039[app:dbg]sdp_codecs_g711u_add_to_media_attrs() g711u: have one at last
18:20:30.039[app:dbg]sdp_codecs_rfc2833_add_to_media_attrs() absent, pt 101
18:20:30.039[app:dbg]sdp_codecs_nse_add_to_media_attrs() absent, pt 0
18:20:30.039[app:dbg]sdp_codecs_ptime_add_to_attrs() ptime present 20
18:20:30.039[app:dbg]sdp_codecs_ecan_add_to_attrs() ecan absent on
18:20:30.039[app:dbg]sdp_codecs_ssup_add_to_attrs() ssup present on
18:20:30.039[app:dbg]sdp_tail:  8 0
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=ptime:20
a=silenceSupp:on - - - -
18:20:30.039[app:dbg]make_sdp: SDP: s=Session SDP
m=audio 23448 RTP/AVP 8 0
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=ptime:20
a=silenceSupp:on - - - -
18:20:30.039[app:dbg]sip: get_support_params: profile 2 supported: 'timer, 100rel, replaces'
18:20:30.039[app:dbg]ITC: [msg_fxs_state] -> group
18:20:30.059[app:dbg]-----[GM] self_fxs_state()
18:20:30.059[app:dbg]Port 4: new state is calling
18:20:30.069[sip]send 863 bytes to udp/[192.168.100.90]:5060 at 01:51:05.830000:
18:20:30.069[sip]   ------------------------------------------------------------------------
18:20:30.069[sip]   INVITE sip:1101@192.168.100.90 SIP/2.0
18:20:30.069[sip]   Via: SIP/2.0/UDP 192.168.100.91;rport;branch=z9hG4bK2SyBBZXS4HH4g
18:20:30.069[sip]   Max-Forwards: 70
18:20:30.069[sip]   From: "1102" <sip:1102@192.168.100.90>;tag=prF7eNUj7ce8m
18:20:30.069[sip]   To: <sip:1101@192.168.100.90>
18:20:30.069[sip]   Call-ID: c81db451-8002-1234-0a8d-a8f94b09c764
18:20:30.069[sip]   CSeq: 3332 INVITE
18:20:30.069[sip]   Contact: <sip:1102@192.168.100.91:5060>
18:20:30.069[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33020174 sofia-sip/1.12.10
18:20:30.069[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
18:20:30.069[sip]   Supported: timer, 100rel, replaces
18:20:30.069[sip]   Session-Expires: 1800
18:20:30.069[sip]   Min-SE: 120
18:20:30.069[sip]   Content-Type: application/sdp
18:20:30.069[sip]   Content-Disposition: session
18:20:30.069[sip]   Content-Length: 228
18:20:30.069[sip]
18:20:30.069[sip]   v=0
18:20:30.069[sip]   o=- 6274427932197667588 5731081406525183482 IN IP4 192.168.100.91
18:20:30.069[sip]   s=Session SDP
18:20:30.069[sip]   c=IN IP4 192.168.100.91
18:20:30.069[sip]   t=0 0
18:20:30.069[sip]   m=audio 23448 RTP/AVP 8 0
18:20:30.069[sip]   a=rtpmap:8 PCMA/8000
18:20:30.069[sip]   a=rtpmap:0 PCMU/8000
18:20:30.069[sip]   a=ptime:20
18:20:30.069[sip]   a=silenceSupp:on - - - -
18:20:30.069[sip]   ------------------------------------------------------------------------
18:20:30.069[sip]recv 540 bytes from udp/[192.168.100.90]:5060 at 01:51:05.850000:
18:20:30.069[sip]   ------------------------------------------------------------------------
18:20:30.069[sip]   SIP/2.0 401 Unauthorized
18:20:30.069[sip]   Via: SIP/2.0/UDP 192.168.100.91;branch=z9hG4bK2SyBBZXS4HH4g;received=192.168.100.91;rport=5060
18:20:30.069[sip]   From: "1102" <sip:1102@192.168.100.90>;tag=prF7eNUj7ce8m
18:20:30.069[sip]   To: <sip:1101@192.168.100.90>;tag=as54f734a3
18:20:30.069[sip]   Call-ID: c81db451-8002-1234-0a8d-a8f94b09c764
18:20:30.069[sip]   CSeq: 3332 INVITE
18:20:30.069[sip]   Server: FPBX-13.0.101(13.8.0)
18:20:30.069[sip]   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
18:20:30.069[sip]   Supported: replaces, timer
18:20:30.069[sip]   WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="79775b4e"
18:20:30.069[sip]   Content-Length: 0
18:20:30.069[sip]
18:20:30.069[sip]   ------------------------------------------------------------------------
18:20:30.069[sip]send 310 bytes to udp/[192.168.100.90]:5060 at 01:51:05.850000:
18:20:30.069[sip]   ------------------------------------------------------------------------
18:20:30.069[sip]   ACK sip:1101@192.168.100.90 SIP/2.0
18:20:30.069[sip]   Via: SIP/2.0/UDP 192.168.100.91;rport;branch=z9hG4bK2SyBBZXS4HH4g
18:20:30.069[sip]   Max-Forwards: 70
18:20:30.079[sip]   From: "1102" <sip:1102@192.168.100.90>;tag=prF7eNUj7ce8m
18:20:30.079[sip]   To: <sip:1101@192.168.100.90>;tag=as54f734a3
18:20:30.079[sip]   Call-ID: c81db451-8002-1234-0a8d-a8f94b09c764
18:20:30.079[sip]   CSeq: 3332 ACK
18:20:30.079[sip]   Content-Length: 0
18:20:30.079[sip]
18:20:30.079[sip]   ------------------------------------------------------------------------
18:20:30.089[app:dbg]got nua_r_set_params : 200(OK)
18:20:30.089[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
18:20:30.089[app:dbg]got nua_i_state : 0(INVITE sent)
18:20:30.089[app:dbg]NO SIP IN nua_i_state == 0 : INVITE sent
18:20:30.089[app:dbg]self_i_state(): call state 2: os : local sdp : sdp_init no_oc
18:20:30.089[app:dbg]sip: call 00040019: SDP offer sent
18:20:30.089[app:dbg]self_create_local_media() 0: add rtpmap 8
18:20:30.089[app:dbg]self_create_local_media() 1: add rtpmap 0
18:20:30.089[app:dbg]sip: call 00040019: media stream 0, creating proposed audio channel, local RTP 192.168.100.91:23448, rtpmaps cnt: 2
18:20:30.089[app:dbg]sip: call 00040019: local SDP offer copy
18:20:30.089[app:dbg]got nua_r_invite : 401(Unauthorized)
18:20:30.089[app:dbg]sip: call 00040019: INVITE: 401 Unauthorized
18:20:30.089[app:dbg]sip: call 00040019: trying to authenticate INVITE
18:20:30.089[app:dbg]auth mode is USER
18:20:30.089[app:dbg]regex ID 4: dial reset
18:20:30.089[sip]send 1029 bytes to udp/[192.168.100.90]:5060 at 01:51:05.870000:
18:20:30.089[sip]   ------------------------------------------------------------------------
18:20:30.089[sip]   INVITE sip:1101@192.168.100.90 SIP/2.0
18:20:30.089[sip]   Via: SIP/2.0/UDP 192.168.100.91;rport;branch=z9hG4bK32Q4cteX1t7pc
18:20:30.089[sip]   Max-Forwards: 70
18:20:30.089[sip]   From: "1102" <sip:1102@192.168.100.90>;tag=prF7eNUj7ce8m
18:20:30.089[sip]   To: <sip:1101@192.168.100.90>
18:20:30.089[sip]   Call-ID: c81db451-8002-1234-0a8d-a8f94b09c764
18:20:30.089[sip]   CSeq: 3333 INVITE
18:20:30.089[sip]   Contact: <sip:1102@192.168.100.91:5060>
18:20:30.089[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33020174 sofia-sip/1.12.10
18:20:30.089[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
18:20:30.089[sip]   Supported: timer, 100rel, replaces
18:20:30.089[sip]   Authorization: Digest username="1102", realm="asterisk", nonce="79775b4e", algorithm=MD5, uri="sip:1101@192.168.100.90", response="da4e516fbed46020a1038f3f289112f1"
18:20:30.089[sip]   Session-Expires: 1800
18:20:30.089[sip]   Min-SE: 120
18:20:30.089[sip]   Content-Type: application/sdp
18:20:30.089[sip]   Content-Disposition: session
18:20:30.089[sip]   Content-Length: 228
18:20:30.089[sip]
18:20:30.089[sip]   v=0
18:20:30.089[sip]   o=- 6274427932197667588 5731081406525183482 IN IP4 192.168.100.91
18:20:30.089[sip]   s=Session SDP
18:20:30.089[sip]   c=IN IP4 192.168.100.91
18:20:30.089[sip]   t=0 0
18:20:30.089[sip]   m=audio 23448 RTP/AVP 8 0
18:20:30.089[sip]   a=rtpmap:8 PCMA/8000
18:20:30.089[sip]   a=rtpmap:0 PCMU/8000
18:20:30.089[sip]   a=ptime:20
18:20:30.089[sip]   a=silenceSupp:on - - - -
18:20:30.099[sip]   ------------------------------------------------------------------------
18:20:30.099[app:dbg]got nua_i_state : 0(INVITE sent)
18:20:30.099[app:dbg]NO SIP IN nua_i_state == 0 : INVITE sent
18:20:30.099[app:dbg]self_i_state(): call state 2: os : local sdp : sdp_sent have_oc
18:20:30.099[sip]recv 521 bytes from udp/[192.168.100.90]:5060 at 01:51:05.880000:
18:20:30.099[sip]   ------------------------------------------------------------------------
18:20:30.099[sip]   SIP/2.0 100 Trying
18:20:30.099[sip]   Via: SIP/2.0/UDP 192.168.100.91;branch=z9hG4bK32Q4cteX1t7pc;received=192.168.100.91;rport=5060
18:20:30.099[sip]   From: "1102" <sip:1102@192.168.100.90>;tag=prF7eNUj7ce8m
18:20:30.099[sip]   To: <sip:1101@192.168.100.90>
18:20:30.099[sip]   Call-ID: c81db451-8002-1234-0a8d-a8f94b09c764
18:20:30.099[sip]   CSeq: 3333 INVITE
18:20:30.099[sip]   Server: FPBX-13.0.101(13.8.0)
18:20:30.099[sip]   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
18:20:30.099[sip]   Supported: replaces, timer
18:20:30.099[sip]   Session-Expires: 1800;refresher=uas
18:20:30.099[sip]   Contact: <sip:1101@192.168.100.90:5060>
18:20:30.099[sip]   Content-Length: 0
18:20:30.099[sip]
18:20:30.099[sip]   ------------------------------------------------------------------------
18:20:30.099[app:dbg]got nua_r_invite : 100(Trying)
18:20:30.099[app:dbg]sip: call 00040019: INVITE: 100 Trying
18:20:30.099[app:dbg]Contact/Record-route on answer to INVITE: sip:1101@192.168.100.90:5060
18:20:30.099[app:dbg]Setup new proxy addr for call; sip:1101@192.168.100.90:5060
18:20:30.099[app:dbg]call 00262169 got 100/Trying - set received_1xx
18:20:30.099[app:dbg]got nua_r_set_params : 200(OK)
18:20:30.099[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
18:20:30.429[sip]recv 916 bytes from udp/[192.168.100.90]:5060 at 01:51:06.210000:
18:20:30.429[sip]   ------------------------------------------------------------------------
18:20:30.429[sip]   INVITE sip:1101@192.168.100.91:5060 SIP/2.0
18:20:30.429[sip]   Via: SIP/2.0/UDP 192.168.100.90:5060;branch=z9hG4bK65cb2df1
18:20:30.429[sip]   Max-Forwards: 70
18:20:30.429[sip]   From: "1102" <sip:1102@192.168.100.90>;tag=as67ebef54
18:20:30.429[sip]   To: <sip:1101@192.168.100.91:5060>
18:20:30.429[sip]   Contact: <sip:1102@192.168.100.90:5060>
18:20:30.429[sip]   Call-ID: 096407ed1506ff1302efa302527e76c4@192.168.100.90:5060
18:20:30.429[sip]   CSeq: 102 INVITE
18:20:30.429[sip]   User-Agent: FPBX-13.0.101(13.8.0)
18:20:30.429[sip]   Date: Mon, 18 Apr 2016 12:20:20 GMT
18:20:30.429[sip]   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
18:20:30.439[sip]   Supported: replaces, timer
18:20:30.439[sip]   Content-Type: application/sdp
18:20:30.439[sip]   Content-Length: 333
18:20:30.439[sip]
18:20:30.439[sip]   v=0
18:20:30.439[sip]   o=root 1846635823 1846635823 IN IP4 192.168.100.90
18:20:30.439[sip]   s=Asterisk PBX 13.8.0
18:20:30.439[sip]   c=IN IP4 192.168.100.90
18:20:30.439[sip]   t=0 0
18:20:30.439[sip]   m=audio 19478 RTP/AVP 0 8 3 111 101
18:20:30.439[sip]   a=rtpmap:0 PCMU/8000
18:20:30.439[sip]   a=rtpmap:8 PCMA/8000
18:20:30.439[sip]   a=rtpmap:3 GSM/8000
18:20:30.439[sip]   a=rtpmap:111 G726-32/8000
18:20:30.439[sip]   a=rtpmap:101 telephone-event/8000
18:20:30.439[sip]   a=fmtp:101 0-16
18:20:30.439[sip]   a=ptime:20
18:20:30.439[sip]   a=maxptime:150
18:20:30.439[sip]   a=sendrecv
18:20:30.439[sip]   ------------------------------------------------------------------------
18:20:30.439[app:dbg]self_pre_invite_param() entering
18:20:30.439[app:dbg]stun_get_public_ip(port = 8000)
18:20:30.439[app:dbg]stun_get_public_ip: Always using local IP
18:20:30.439[app:dbg]sip: simple call (7) profile(2)
18:20:30.439[app:dbg]sip: get_support_params: profile 2 supported: 'timer, 100rel, replaces'
18:20:30.439[sip]send 334 bytes to udp/[192.168.100.90]:5060 at 01:51:06.220000:
18:20:30.439[sip]   ------------------------------------------------------------------------
18:20:30.439[sip]   SIP/2.0 100 Trying
18:20:30.439[sip]   Via: SIP/2.0/UDP 192.168.100.90:5060;branch=z9hG4bK65cb2df1
18:20:30.439[sip]   From: "1102" <sip:1102@192.168.100.90>;tag=as67ebef54
18:20:30.439[sip]   To: <sip:1101@192.168.100.91:5060>
18:20:30.439[sip]   Call-ID: 096407ed1506ff1302efa302527e76c4@192.168.100.90:5060
18:20:30.439[sip]   CSeq: 102 INVITE
18:20:30.439[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33020174 sofia-sip/1.12.10
18:20:30.439[sip]   Content-Length: 0
18:20:30.439[sip]
18:20:30.439[sip]   ------------------------------------------------------------------------
18:20:30.449[app:dbg]got nua_i_invite : 100(Trying)
18:20:30.449[app:dbg]NO CALL IN nua_i_invite == 100 : Trying
18:20:30.449[app:dbg]stun_get_public_ip(port = 8000)
18:20:30.449[app:dbg]stun_get_public_ip: Always using local IP
18:20:30.449[app:dbg]sip: get_support_params: profile 2 supported: 'timer, 100rel, replaces'
18:20:30.449[app:dbg]sip: INVITE from sip:1102@192.168.100.90
18:20:30.449[app:dbg]simple call
18:20:30.449[app:dbg]stun_get_public_ip(port = 8000)
18:20:30.449[app:dbg]stun_get_public_ip: Always using local IP
18:20:30.449[app:dbg]replaces 1, have accepted 0, ep 0x1b9384, state 1
18:20:30.449[app:dbg]available RTP ports: 23000...26000
18:20:30.449[app:dbg]selected port for current call: 23452
18:20:30.449[app:dbg]self_i_invite (8694): no alert_info received
18:20:30.449[app:dbg]sdp_codecs_init() init call sdp (empty)
18:20:30.449[app:dbg]sdp_codecs_set_ssup() ssup present 0 ssup yes
18:20:30.449[app:dbg]G711U: PT 0
18:20:30.449[app:dbg]sdp_codecs_add_g711u_item() pt 0
18:20:30.449[app:dbg]G711A: PT 8
18:20:30.449[app:dbg]sdp_codecs_add_g711a_item() pt 8
18:20:30.449[app:dbg]sdp_codecs_set_rfc2833() have no common rfc2833 events
18:20:30.449[app:dbg]sdp_codecs_set_rfc2833() present pt 101 remote fmtp 0-16, local fmtp
18:20:30.449[app:dbg]attr: name: ptime value: 20
18:20:30.449[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:20:30.449[app:dbg]attr: name: maxptime value: 150
18:20:30.449[app:dbg]sdp_codecs_dump() ssup absent on, ecan absent on, rfc present 101, nse absent 0, ptime present 20
18:20:30.449[app:dbg]sdp_codecs_dump() G723: none
18:20:30.449[app:dbg]sdp_codecs_dump() G711A:
18:20:30.449[app:dbg]sdp_codecs_dump() PT 8, vbd absent off
18:20:30.449[app:dbg]sdp_codecs_dump() G711U:
18:20:30.449[app:dbg]sdp_codecs_dump() PT 0, vbd absent off
18:20:30.449[app:dbg]stun_get_public_ip(port = 23452)
18:20:30.449[app:dbg]stun_get_public_ip: Always using local IP
18:20:30.449[app:dbg]self_i_invite: handle call id 0x02070017, call id 0x02070017
18:20:30.449[app:dbg]got nua_i_state : 100(Trying)
18:20:30.449[app:dbg]NO SIP IN nua_i_state == 100 : Trying
18:20:30.449[app:dbg]self_i_state(): call state 5: or : remote sdp : sdp_init no_oc
18:20:30.449[app:dbg]sip: call 02070017: SDP offer received
18:20:30.449[app:dbg]sdp_codecs_init() init call sdp (offer)
18:20:30.449[app:dbg]sdp_codecs_set_ssup() ssup present 0 ssup yes
18:20:30.449[app:dbg]sdp_codecs_set_rfc2833() have no common rfc2833 events
18:20:30.449[app:dbg]sdp_codecs_set_rfc2833() present pt 101 remote fmtp 0-16, local fmtp
18:20:30.449[app:dbg]attr: name: ptime value: 20
18:20:30.449[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:20:30.449[app:dbg]attr: name: maxptime value: 150
18:20:30.449[app:dbg]sip: call 02070017: media stream 0, creating proposed audio channel, remote RTP 192.168.100.90:19478
18:20:30.449[app:dbg]sip: call 02070017: select audio media
18:20:30.449[app:dbg]G711U: PT 0
18:20:30.449[app:dbg]G711A: PT 8
18:20:30.449[app:dbg]sip: call 02070017: remote SDP offer copy
18:20:30.449[app:dbg]sip: call 02070017: called from sip:1102@192.168.100.90 to sip:1101@192.168.100.91:5060
18:20:30.449[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
18:20:30.449[app:dbg]sip -[msg_call]-> pbx
18:20:30.449[app:dbg]self_callstate_received (6934): complete
18:20:30.449[app:dbg]ITC: [msg_call] -> pbx
18:20:30.449[app:dbg]SLIC 7: incoming call from 192.168.100.90:5060/1102("1102") payload 101 call ID: 02070017 group: -1
18:20:30.449[app:dbg]pbx: allocating memory for new call
18:20:30.449[app:dbg]pbx: created new incoming call for SLIC 7
18:20:30.449[app:dbg]self_call_create (4455): created
18:20:30.449[app:dbg]SLIC 7: -> ringing
18:20:30.449[app:info]SLIC 7: from state 'hangup' to state 'ringing'
18:20:30.449[app:dbg]CMD_CREATE_CONN: port = 7
18:20:30.449[app:dbg]Port 7: check vapi queue ('free') at vapi_create_chan:694
18:20:30.449[app:dbg]Chan 7: current state is INITIAL
18:20:30.449[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'create' at vapi_create_chan:720
18:20:30.459[app:dbg]got nua_r_set_params : 200(OK)
18:20:30.459[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
18:20:30.459[sip]recv 537 bytes from udp/[192.168.100.90]:5060 at 01:51:06.240000:
18:20:30.459[sip]   ------------------------------------------------------------------------
18:20:30.459[sip]   SIP/2.0 180 Ringing
18:20:30.459[sip]   Via: SIP/2.0/UDP 192.168.100.91;branch=z9hG4bK32Q4cteX1t7pc;received=192.168.100.91;rport=5060
18:20:30.459[sip]   From: "1102" <sip:1102@192.168.100.90>;tag=prF7eNUj7ce8m
18:20:30.459[sip]   To: <sip:1101@192.168.100.90>;tag=as33312270
18:20:30.459[sip]   Call-ID: c81db451-8002-1234-0a8d-a8f94b09c764
18:20:30.459[sip]   CSeq: 3333 INVITE
18:20:30.459[sip]   Server: FPBX-13.0.101(13.8.0)
18:20:30.459[sip]   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
18:20:30.459[sip]   Supported: replaces, timer
18:20:30.459[sip]   Session-Expires: 1800;refresher=uas
18:20:30.459[sip]   Contact: <sip:1101@192.168.100.90:5060>
18:20:30.459[sip]   Content-Length: 0
18:20:30.459[sip]
18:20:30.459[sip]   ------------------------------------------------------------------------
18:20:30.459[app:dbg]got nua_r_invite : 180(Ringing)
18:20:30.459[app:dbg]sip: call 00040019: INVITE: 180 Ringing
18:20:30.459[app:dbg]Contact/Record-route on answer to INVITE: sip:1101@192.168.100.90:5060
18:20:30.459[app:dbg]Setup new proxy addr for call; sip:1101@192.168.100.90:5060
18:20:30.459[app:dbg]call 00262169 got 180/Ringing - set received_1xx
18:20:30.459[app:dbg]sip: call 00040019: ringing back
18:20:30.459[app:WARN]No SDP description!!!
18:20:30.459[app:dbg]sip: call 00040019: 180 ringing without SDP descr
18:20:30.459[app:dbg]sip -[msg_free]-> pbx
18:20:30.459[app:dbg]got nua_i_state : 180(Ringing)
18:20:30.459[app:dbg]NO SIP IN nua_i_state == 180 : Ringing
18:20:30.459[app:dbg]self_i_state(): call state 3: : : sdp_sent have_oc
18:20:30.459[app:dbg]got nua_r_set_params : 200(OK)
18:20:30.459[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
18:20:30.459[app:dbg]got nua_r_set_params : 200(OK)
18:20:30.459[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
18:20:30.459[app:dbg]VQ Conn 7 = MSP :        'create' =
18:20:30.459[app:dbg]Creating connection 7....
18:20:30.459[app:dbg]Chan 7: INITIAL -> CREATING
18:20:30.459[app:dbg]Created succefuly 7....
18:20:30.459[app:info]SLIC 7: has incoming call from 1102
18:20:30.469[app:dbg]port 7: port_seize
18:20:30.469[app:dbg]port 7: seize
18:20:30.469[app:dbg]port 7: seize has cadence pulse = 0, pause = 0
18:20:30.469[app:dbg]Set port 7 led to state 'LED_RINGING'
18:20:30.469[app:dbg]Port 7: user port 1, old state ringing, new state
18:20:30.469[app:dbg]Set port 7 led to state 'LED_OFF'
18:20:30.469[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x0000004f
18:20:30.469[app:dbg]pbx -[msg_fxs_state]-> group
18:20:30.469[app:dbg]ITC: [msg_fxs_state] -> group
18:20:30.469[app:dbg]-----[GM] self_fxs_state()
18:20:30.469[app:dbg]Port 7: new state is ringing
18:20:30.489[app:dbg]pbx -[msg_free]-> sip
18:20:30.489[app:dbg]SLIC 7: list of all calls:
18:20:30.489[app:dbg]   call ID: 02070017
18:20:30.489[app:dbg]incom_calls_add() add call 0x02070017, group -1, task <sip> to list
18:20:30.489[app:dbg]vapi_proc_event: VAPI_CB
18:20:30.489[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x0000004f result 0x00000000
18:20:30.489[app:dbg]slic7. Event 6.
18:20:30.489[app:dbg]slic 7. Ring on event
18:20:30.489[app:dbg]Set port 7 led to state 'LED_RINGING'
18:20:30.489[app:dbg]ITC: [msg_free] -> sip
18:20:30.489[app:dbg]sip: call 02070017: endpoint 7 ringing
18:20:30.489[app:dbg]sip: call 02070017,sip: INVITE: 180 Ringing
18:20:30.489[app:dbg]send_18x() call 0x02070017, hdr <none>, sip, rel mode/cfg off/supp/req, inv w/ sdp, to port
18:20:30.489[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:20:30.489[app:dbg]sdp_codecs_dump() ssup absent on, ecan absent on, rfc present 101, nse absent 0, ptime present 20
18:20:30.489[app:dbg]sdp_codecs_dump() G723: none
18:20:30.489[app:dbg]sdp_codecs_dump() G711A:
18:20:30.489[app:dbg]sdp_codecs_dump() PT 8, vbd absent off
18:20:30.489[app:dbg]sdp_codecs_dump() G711U:
18:20:30.489[app:dbg]sdp_codecs_dump() PT 0, vbd absent off
18:20:30.489[app:dbg]sdp_codecs_g711a_add_to_media_attrs() g711a: have one at last
18:20:30.489[app:dbg]sdp_codecs_g711u_add_to_media_attrs() g711u: have one at last
18:20:30.489[app:dbg]sdp_codecs_rfc2833_add_to_media_attrs() present, pt 101
18:20:30.489[app:dbg]sdp_codecs_nse_add_to_media_attrs() absent, pt 0
18:20:30.489[app:dbg]sdp_codecs_ptime_add_to_attrs() ptime present 20
18:20:30.489[app:dbg]sdp_codecs_ecan_add_to_attrs() ecan absent on
18:20:30.489[app:dbg]sdp_codecs_ssup_add_to_attrs() ssup absent on
18:20:30.489[app:dbg]sdp_tail:  8 0
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=ptime:20
18:20:30.489[app:dbg]make_sdp: SDP: s=Session SDP
m=audio 23452 RTP/AVP 8 0
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=ptime:20
18:20:30.489[app:dbg]send_18x(): respond w/o sdp 0, sdp 1
18:20:30.489[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
18:20:30.489[app:dbg]Early media is enabled
18:20:30.489[app:dbg]Sending 183 Session progress with SDP
18:20:30.489[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000000
18:20:30.499[app:dbg]port_process (11051): seize next tone
18:20:30.499[app:dbg]port 7: clear
18:20:30.499[app:dbg]Set port 7 led to state 'LED_OFF'
18:20:30.499[app:dbg]port 7: port_seize
18:20:30.499[app:dbg]port 7: seize
18:20:30.499[app:dbg]port 7: seize has cadence pulse = 1000, pause = 4000
18:20:30.499[app:dbg]Set port 7 led to state 'LED_RINGING'
18:20:30.499[app:dbg]ITC: [msg_free] -> pbx
18:20:30.499[app:dbg]SLIC 4: peer ringing
18:20:30.499[app:dbg]SLIC 4: -> ringback (1)
18:20:30.499[app:info]SLIC 4: from state 'calling' to state 'ringback'
18:20:30.499[sip]send 778 bytes to udp/[192.168.100.90]:5060 at 01:51:06.280000:
18:20:30.499[sip]   ------------------------------------------------------------------------
18:20:30.499[sip]   SIP/2.0 183 Session Progress
18:20:30.499[sip]   Via: SIP/2.0/UDP 192.168.100.90:5060;branch=z9hG4bK65cb2df1
18:20:30.499[sip]   From: "1102" <sip:1102@192.168.100.90>;tag=as67ebef54
18:20:30.499[sip]   To: <sip:1101@192.168.100.91:5060>;tag=Q18Zggcp4N4tg
18:20:30.499[sip]   Call-ID: 096407ed1506ff1302efa302527e76c4@192.168.100.90:5060
18:20:30.499[sip]   CSeq: 102 INVITE
18:20:30.499[sip]   Contact: <sip:1101@192.168.100.91:5060>
18:20:30.499[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33020174 sofia-sip/1.12.10
18:20:30.499[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
18:20:30.499[sip]   Supported: timer, 100rel, replaces
18:20:30.499[sip]   Content-Type: application/sdp
18:20:30.499[sip]   Content-Disposition: session
18:20:30.499[sip]   Content-Length: 178
18:20:30.499[sip]
18:20:30.499[sip]   v=0
18:20:30.499[sip]   o=- 8651219803159688580 6772942873527236150 IN IP4 192.168.100.91
18:20:30.499[sip]   s=Session SDP
18:20:30.499[sip]   c=IN IP4 192.168.100.91
18:20:30.499[sip]   t=0 0
18:20:30.499[sip]   m=audio 23452 RTP/AVP 8
18:20:30.499[sip]   a=rtpmap:8 PCMA/8000
18:20:30.499[sip]   a=ptime:20
18:20:30.499[sip]   ------------------------------------------------------------------------
18:20:30.499[app:dbg]got nua_i_state : 183(Session Progress)
18:20:30.499[app:dbg]NO SIP IN nua_i_state == 183 : Session Progress
18:20:30.499[app:dbg]self_i_state(): call state 6: as : local sdp : sdp_recv no_oc
18:20:30.499[app:dbg]sip: call 02070017: SDP answer sent for the first invite
18:20:30.499[app:dbg]self_destroy_current_media() nothing to destroy
18:20:30.499[app:dbg]self_start_media: 1. handle call id 0x02070017, call id 0x02070017
18:20:30.499[app:dbg]sip: set options: call 02070017: media stream 0: 192.168.100.91:23452 -> 192.168.100.90:19478: MFPT 0 <drop>
18:20:30.499[app:dbg]self_itc_codec(): payload 8
18:20:30.509[app:dbg]self_itc_codec(): payload 8
18:20:30.509[app:dbg]Supported codec[0]: <G.711A>:8, vbd off, vad on, ecan on
18:20:30.509[app:dbg]sdp_codecs_get_rfc2833: present=1 pt=101
18:20:30.509[app:dbg]validate_ptime() codec G.711A, ptime 20, check_bigger 1, present 1
18:20:30.509[app:dbg]validate_ptime() using 20
18:20:30.509[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:20:30.509[app:dbg]self_start_media: 2. handle call id 0x02070017, call id 0x02070017
18:20:30.509[app:dbg]sip -[msg_set_media]-> pbx
18:20:30.509[app:dbg]sip: call 02070017: local SDP offer copy
18:20:30.529[app:dbg]port_start_tone(4 23 0 0)
18:20:30.529[app:dbg]CMD_START_TONE: port = 4
18:20:30.529[app:dbg]Port 4: check vapi queue ('free') at vapi_start_tone_chan:1384
18:20:30.529[app:dbg]Chan 4: current state is CREATED
18:20:30.529[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'start_tone' at vapi_start_tone_chan:1421
18:20:30.529[app:dbg]VQ Conn 4 = MSP :    'start_tone' =
18:20:30.529[app:dbg]chan 4 start tone, id=23, direction=TDM
18:20:30.529[app:dbg]Port 4: user port 2, old state ringback, new state
18:20:30.529[app:dbg]Set port 4 led to state 'LED_ON'
18:20:30.529[app:dbg]pbx -[msg_fxs_state]-> group
18:20:30.529[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000922
18:20:30.529[app:dbg]ITC: [msg_fxs_state] -> group
18:20:30.529[app:dbg]-----[GM] self_fxs_state()
18:20:30.529[app:dbg]Port 4: new state is ringback
18:20:30.549[app:dbg]vapi_proc_event: VAPI_CB
18:20:30.549[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000000 result 0x00000000
18:20:30.549[app:dbg]vapi: Conn 7 - << CREATED >>
18:20:30.549[app:dbg]vapi: Conn 7 - fix DTMF detector
18:20:30.549[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000049
18:20:30.559[app:dbg]vapi_proc_event: VAPI_CB
18:20:30.559[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000922 result 0x00000000
18:20:30.559[app:dbg]Conn 4: Start tone - Successfull
18:20:30.559[app:dbg]Port 4: check vapi queue ('busy''start_tone') at vapi_next_ops:2532
18:20:30.569[app:dbg]vapi_proc_event: VAPI_CB
18:20:30.569[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000049 result 0x00000000
18:20:30.569[app:dbg]vapi: Conn 7 - fix CNG generator
18:20:30.569[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x0000004c
18:20:30.579[app:dbg]ITC: [msg_set_media] -> pbx
18:20:30.579[app:dbg]self_on_set_media: call id 0x02070017 tx/rx 1/1
18:20:30.579[app:dbg]dump_port_calls() SLIC 7:
18:20:30.579[app:dbg]Q:(0x329800,0x02070017,(nil))
18:20:30.579[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:20:30.579[app:dbg]SLIC 7: TX start / RX start: 192.168.100.91:23452->192.168.100.90:19478, <G.711A:8>
18:20:30.579[app:dbg]SLIC 7: send only 0 vad 1 g723_hr 1 vbd 0, ecan 1 rfc2833 pt 101, NSE pt 0, MFPT 0
18:20:30.579[app:dbg]incom_calls_set_media_started() call 0x02070017, group -1, task <sip> media started
18:20:30.579[app:dbg]self_set_media_start(): set ptime to 20
18:20:30.579[app:dbg]port_set_ip_param
18:20:30.579[app:dbg]set media param for '7', 192.168.100.91:23452, mode=local, random 60
18:20:30.579[app:dbg]port_set_ip_param
18:20:30.579[app:dbg]set media param for '7', 192.168.100.90:19478, mode=remote, random 60
18:20:30.579[app:dbg]CMD_CREATE_CONN: port = 7
18:20:30.579[app:dbg]Port 7: check vapi queue ('busy''create') at vapi_create_chan:694
18:20:30.579[app:dbg]Port 7 put cmd 'create',cur 'create' to queue at (vapi_create_chan:700)
18:20:30.579[app:dbg]VQ Conn 7 = MSP :        'create' =
18:20:30.579[app:dbg]VQ Conn 7 + 01  :        'create'  + <-get_ptr
18:20:30.579[app:dbg]SLIC 7: starting media (G.711A) 192.168.100.91:23452 -> 192.168.100.90:19478
18:20:30.579[app:dbg]port 7: start voice - first time
18:20:30.579[app:dbg]port_start_voice() chan 07: remote IP <192.168.100.90> (arp query 0 times)
18:20:30.579[app:dbg]chan 7: get mac succesfull, repeat 0 times
18:20:30.579[app:dbg]CMD_START_VOICE: port = 7
18:20:30.579[app:dbg]vapi_set_chan_param: chan=7 hold=0 deactivate=0
18:20:30.579[app:dbg]Port 7: check vapi queue ('busy''create') at vapi_set_chan_param:2136
18:20:30.579[app:dbg]Port 7 put cmd 'start voice',cur 'create' to queue at (vapi_set_chan_param:2148)
18:20:30.579[app:dbg]VQ Conn 7 = MSP :        'create' =
18:20:30.579[app:dbg]VQ Conn 7 + 01  :        'create'  + <-get_ptr
18:20:30.579[app:dbg]VQ Conn 7 + 02  :   'start voice'  +
18:20:30.579[app:dbg]vapi_proc_event: VAPI_CB
18:20:30.579[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x0000004c result 0x00000000
18:20:30.579[app:dbg]vapi: Conn 7 - caller id Set param
18:20:30.579[app:dbg]vapi: chan '7' set param Caller ID
18:20:30.579[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x0000000c
18:20:30.589[app:dbg]vapi_proc_event: VAPI_CB
18:20:30.589[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x0000000c result 0x00000000
18:20:30.589[app:dbg]vapi: Conn 7 - enable ind ptime and pt
18:20:30.589[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x0000004a
18:20:30.599[app:dbg]vapi_proc_event: VAPI_CB
18:20:30.599[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x0000004a result 0x00000000
18:20:30.599[app:dbg]Chan 7: CREATING -> CREATED
18:20:30.599[app:dbg]Port 7: check vapi queue ('busy''create') at vapi_next_ops:2532
18:20:30.599[app:dbg]Port 7 get cmd 'create' from queue at (vapi_next_ops:2551)
18:20:30.599[app:dbg]VQ Conn 7 + 02  :   'start voice'  + <-get_ptr
18:20:30.599[app:dbg]Port 7: check vapi queue ('free') at vapi_create_chan:694
18:20:30.599[app:dbg]Chan 7: current state is CREATED
18:20:30.599[app:dbg]chan 7: no need to create - already exists
18:20:30.599[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2694
18:20:30.599[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2532
18:20:30.599[app:dbg]Port 7 get cmd 'start voice' from queue at (vapi_next_ops:2551)
18:20:30.599[app:dbg]vapi_set_chan_param: chan=7 hold=0 deactivate=0
18:20:30.599[app:dbg]Port 7: check vapi queue ('free') at vapi_set_chan_param:2136
18:20:30.599[app:dbg]Chan 7: current state is CREATED
18:20:30.599[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'start voice' at vapi_set_chan_param:2160
18:20:30.599[app:dbg]VQ Conn 7 = MSP :   'start voice' =
18:20:30.599[app:dbg]Conn 7 Eth src=a8:f9:4b:09:c7:64, dst=00:00:00:00:00:00
18:20:30.599[app:dbg]Conn 7 IP src=192.168.100.91:23452, dst=192.168.100.90:19478
18:20:30.599[app:dbg]CHECK REQID: 0x00000502(Conn 7)
18:20:30.599[app:dbg]vapi: Conn 7. Disable - Ok
18:20:30.599[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000502
18:20:30.609[app:dbg]vapi_proc_event: VAPI_CB
18:20:30.609[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000502 result 0x00000000
18:20:30.609[app:dbg]VOIP_DISABLE: chan = 7
18:20:30.609[app:dbg]vapi_cb_setchan: chan 7 deactivate 0
18:20:30.609[app:dbg]vapi: create: TDM channel 7 Set SSRC to 3ABE2172
18:20:30.609[app:dbg]vapi: Conn 7. Set src/dst eth mac - Ok
18:20:30.609[app:dbg]Reserved IP: 192.168.253.1
18:20:30.609[app:dbg]vapi_cb_setchan: ch7. msp_ip = 192.168.253.2
18:20:30.609[app:dbg]IP PARAMS: 1FDA8C0 30452 2FDA8C0 30452
18:20:30.609[app:dbg]vapi: Conn 7. Set src/dst ip addr - ok
18:20:30.609[app:dbg]Create RX-TX media for SLIC 7(sendonly: 0, rtcp: 0)
18:20:30.609[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000508
18:20:30.619[app:dbg]vapi_proc_event: VAPI_CB
18:20:30.619[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000508 result 0x00000000
18:20:30.619[app:dbg]VOIP_SET_IP: chan = 7
18:20:30.619[app:dbg]vapi_cb_setchan: chan 7 deactivate 0
18:20:30.619[app:dbg]chan 7. vapi_cb_setchan: configure ecan on
18:20:30.619[app:dbg]vapi_passthru_echocan_cb() NLP, DCRF enabled, session 0, on 1, value 0x8007
18:20:30.619[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000547
18:20:30.629[app:dbg]vapi_proc_event: VAPI_CB
18:20:30.629[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000547 result 0x00000000
18:20:30.629[app:dbg]VOIP_SSRC_FILT: chan = 7
18:20:30.629[app:dbg]vapi_cb_setchan: chan 7 deactivate 0
18:20:30.629[app:dbg]chan 7. vapi_cb_setchan: VOIP_SSRC_FILT
18:20:30.629[app:dbg]vapi_cb_setchan: ch7. msp_ip = 192.168.253.2
18:20:30.629[app:dbg]RTCP IP PARAMS: 1FDA8C0 30453 2FDA8C0 30453
18:20:30.629[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x0000052b
18:20:30.639[app:dbg]vapi_proc_event: VAPI_CB
18:20:30.639[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x0000052b result 0x00000000
18:20:30.639[app:dbg]VOIP_SET_IP2: chan = 7
18:20:30.639[app:dbg]vapi_cb_setchan: chan 7 deactivate 0
18:20:30.639[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_PT
18:20:30.639[app:dbg]for chan <7> set codec type = 5 'G711A'
18:20:30.639[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x0000054e
18:20:30.649[app:dbg]vapi_proc_event: VAPI_CB
18:20:30.649[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x0000054e result 0x00000000
18:20:30.649[app:dbg]UNKNOWN_CMD: chan = 7
18:20:30.649[app:dbg]vapi_cb_setchan: chan 7 deactivate 0
18:20:30.649[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_CODEC
18:20:30.649[app:dbg]set_packet_interval = 20
18:20:30.649[app:dbg]vapi: Conn 7. Set 'Packet interval' 20
18:20:30.649[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_PACKET
18:20:30.649[app:dbg]SET TX PT: 101
18:20:30.649[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000510
18:20:30.659[app:dbg]vapi_proc_event: VAPI_CB
18:20:30.659[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000510 result 0x00000000
18:20:30.659[app:dbg]VOIP_SET_PACKET2: chan = 7
18:20:30.659[app:dbg]vapi_cb_setchan: chan 7 deactivate 0
18:20:30.659[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_PACKET2
18:20:30.659[app:dbg]SET RX PT: 101
18:20:30.659[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000513
18:20:30.669[app:dbg]vapi_proc_event: VAPI_CB
18:20:30.669[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000513 result 0x00000000
18:20:30.669[app:dbg]VOIP_SET_DTMFOPT: chan = 7
18:20:30.669[app:dbg]vapi_cb_setchan: chan 7 deactivate 0
18:20:30.669[app:dbg]vapi: Chan 7 set chach (packet mode)
18:20:30.669[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_DTMFOPT dtmf 0, pt 101
18:20:30.669[app:dbg]Enable voice DTMF tones
18:20:30.669[app:dbg]Set RFC2833 PT: 101(01A5, 65FF)
18:20:30.669[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_DTMFOPT2
18:20:30.669[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_PT2
18:20:30.669[app:dbg]vapi: Conn 7. Enable RTP indication
18:20:30.669[app:dbg]chan 7. vapi_cb_setchan: VOIP_ENABLE_RTP_IND
18:20:30.669[app:dbg]chan 7: set jitter buffer options
18:20:30.669[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_INDCTL
18:20:30.669[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_JBOPT
18:20:30.669[app:dbg]vapi: Conn 7. Set tone ctl options
18:20:30.669[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_VLAN
18:20:30.669[app:dbg]VAD: 1 CNG: 0 PTE: 20
18:20:30.669[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000516
18:20:30.679[app:dbg]vapi_proc_event: VAPI_CB
18:20:30.679[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000516 result 0x00000000
18:20:30.679[app:dbg]VOIP_SET_VCEOPT: chan = 7
18:20:30.679[app:dbg]vapi_cb_setchan: chan 7 deactivate 0
18:20:30.679[app:dbg]chan 7. vapi_cb_setchan: VOIP_SET_VCEOPT
18:20:30.679[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000518
18:20:30.689[app:dbg]vapi_proc_event: VAPI_CB
18:20:30.689[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000518 result 0x00000000
18:20:30.689[app:dbg]VOIP_SET_VOICE: chan = 7
18:20:30.689[app:dbg]vapi_cb_setchan: chan 7 deactivate 0
18:20:30.689[app:dbg]vapi_cb_setchan() Conn 7: set eActive state ok
18:20:30.689[app:dbg]vapi_cb_setchan() Conn 7: creating connection at state ps_ringing - early media mode
18:20:30.689[app:dbg]port 7: mute media for generating caller id
18:20:30.689[app:dbg]Port 7: check vapi queue ('busy''start voice') at vapi_next_ops:2532
18:20:30.689[app:dbg]Mute all RX-TX medias on SLIC 7
18:20:30.689[app:dbg]Mute media on chan 7[mute 1]
18:20:31.529[app:dbg]slic7. Event 7.
18:20:31.529[app:dbg]slic 7. Ring off event
18:20:31.529[app:dbg]Set port 7 led to state 'LED_OFF'
18:20:31.529[app:dbg]Set port 7 led to state 'LED_OFF'
18:20:32.059[app:info]SLIC 7: FSK caller-id generated
18:20:32.059[app:dbg]CMD_START_CID: port = 7
18:20:32.059[app:dbg]Port 7: check vapi queue ('free') at vapi_generate_offhook_caller_id:2885
18:20:32.059[app:dbg]Chan 7: current state is CREATED
18:20:32.059[app:info]Channel 7. Caller-ID type I. Phone: <1102>, name:<"1102">
18:20:32.059[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'gen_offhook_caller_id' at vapi_generate_offhook_caller_id:2906
18:20:32.059[app:dbg]VQ Conn 7 = MSP : 'gen_offhook_caller_id' =
18:20:32.059[app:dbg]Caller ID date: 116.4.18 18:20:32
18:20:32.059[app:dbg]vapi: chan '7' generate Caller ID len=26
18:20:32.059[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000a35
18:20:32.059[app:dbg]vapi_proc_event: VAPI_CB
18:20:32.059[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000a35 result 0x00000000
18:20:32.059[app:dbg]chan 7: Offhook Caller ID generated
18:20:32.059[app:dbg]Port 7: check vapi queue ('busy''gen_offhook_caller_id') at vapi_next_ops:2532
18:20:32.739[app:dbg]vapi: generic event, code 9 <Caller Id cmplt>, conn 7
18:20:32.739[app:dbg]vapi_proc_event: eVAPI_CALLER_ID_CMPLT_EVENT chan 7 CmpltCause 0
18:20:32.739[app:dbg]vapi_proc_event() Conn 7: early media mode - restart ringback tone to IP
18:20:32.739[app:dbg]port_start_tone(7 23 1 0)
18:20:32.739[app:dbg]CMD_START_TONE: port = 7
18:20:32.739[app:dbg]Port 7: check vapi queue ('free') at vapi_start_tone_chan:1384
18:20:32.739[app:dbg]Chan 7: current state is CREATED
18:20:32.739[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'start_tone' at vapi_start_tone_chan:1421
18:20:32.739[app:dbg]VQ Conn 7 = MSP :    'start_tone' =
18:20:32.739[app:dbg]chan 7 start tone, id=23, direction=Packet
18:20:32.739[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000922
18:20:32.749[app:dbg]Unmute all RX-TX medias on SLIC 7
18:20:32.749[app:dbg]Unmute media on chan 7[mute 0]
18:20:32.749[app:dbg]VQ Conn 7 = MSP :    'start_tone' =
18:20:32.749[app:dbg]vapi_proc_event: VAPI_CB
18:20:32.749[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000922 result 0x00000000
18:20:32.749[app:dbg]Conn 7: Start tone - Successfull
18:20:32.749[app:dbg]Port 7: check vapi queue ('busy''start_tone') at vapi_next_ops:2532
18:20:34.459[app:dbg]slic7. Event 2.
18:20:34.459[app:dbg]slic 7. Off-hook event
18:20:34.459[app:dbg]Set port 7 led to state 'LED_ON'
18:20:34.459[app:dbg]HIO: offhook TDM port '7' port enabled 1
18:20:34.459[app:dbg]SLIC 7 (1101): offhook state: ringing
18:20:34.459[app:dbg]regex ID 7: dial reset
18:20:34.459[app:dbg]SLIC 7: -> talking(call id: 02070017)
18:20:34.459[app:dbg]pbx -[msg_answer]-> sip
18:20:34.459[app:info]SLIC 7: from state 'ringing' to state 'talking'
18:20:34.459[app:dbg]CMD_STOP_TONE: port = 7
18:20:34.459[app:dbg]Port 7: check vapi queue ('free') at vapi_stop_tone_chan:1474
18:20:34.459[app:dbg]Chan 7: current state is CREATED
18:20:34.459[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'stop_tone' at vapi_stop_tone_chan:1520
18:20:34.459[app:dbg]VQ Conn 7 = MSP :     'stop_tone' =
18:20:34.459[app:dbg]chan 7 stop tone
18:20:34.459[app:dbg]ITC: [msg_answer] -> sip
18:20:34.459[app:dbg]sip: call 02070017: endpoint 7 answered
18:20:34.459[app:dbg]sip: call 02070017: INVITE: 200 OK SIP_T NO
18:20:34.459[app:dbg]sip: call 02070017: set endpoint 7
18:20:34.459[app:dbg]self_on_answer() sdp state <init> - create offer sdp, ptime present/20
18:20:34.459[app:dbg]sdp_codecs_init() init call sdp (offer)
18:20:34.459[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:20:34.459[app:dbg]sdp_codecs_dump() ssup present on, ecan absent on, rfc absent 101, nse absent 0, ptime present 20
18:20:34.459[app:dbg]sdp_codecs_dump() G723: none
18:20:34.459[app:dbg]sdp_codecs_dump() G711A:
18:20:34.459[app:dbg]sdp_codecs_dump() PT 8, vbd absent off
18:20:34.459[app:dbg]sdp_codecs_dump() G711U:
18:20:34.459[app:dbg]sdp_codecs_dump() PT 0, vbd absent off
18:20:34.459[app:dbg]sdp_codecs_g711a_add_to_media_attrs() g711a: have one at last
18:20:34.459[app:dbg]sdp_codecs_g711u_add_to_media_attrs() g711u: have one at last
18:20:34.459[app:dbg]sdp_codecs_rfc2833_add_to_media_attrs() absent, pt 101
18:20:34.459[app:dbg]sdp_codecs_nse_add_to_media_attrs() absent, pt 0
18:20:34.459[app:dbg]sdp_codecs_ptime_add_to_attrs() ptime present 20
18:20:34.459[app:dbg]sdp_codecs_ecan_add_to_attrs() ecan absent on
18:20:34.459[app:dbg]sdp_codecs_ssup_add_to_attrs() ssup present on
18:20:34.459[app:dbg]sdp_tail:  8 0
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=ptime:20
a=silenceSupp:on - - - -
18:20:34.459[app:dbg]make_sdp: SDP: s=Session SDP
m=audio 23452 RTP/AVP 8 0
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=ptime:20
a=silenceSupp:on - - - -
18:20:34.459[app:dbg]sdp_codecs_get_rfc2833: present=0 pt=101
18:20:34.459[app:WARN][get_group_profile_id]-1 is not group index!!!!
18:20:34.459[app:dbg]self_on_answer: call_id = 02070017 need_exchange_at_answer = 0
18:20:34.459[app:dbg]Unmute all RX-TX medias on SLIC 7
18:20:34.459[app:dbg]Unmute media on chan 7[mute 0]
18:20:34.459[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000923
18:20:34.479[sip]send 830 bytes to udp/[192.168.100.90]:5060 at 01:51:10.240000:
18:20:34.479[sip]   ------------------------------------------------------------------------
18:20:34.479[sip]   SIP/2.0 200 OK
18:20:34.479[sip]   Via: SIP/2.0/UDP 192.168.100.90:5060;branch=z9hG4bK65cb2df1
18:20:34.479[sip]   From: "1102" <sip:1102@192.168.100.90>;tag=as67ebef54
18:20:34.479[sip]   To: <sip:1101@192.168.100.91:5060>;tag=Q18Zggcp4N4tg
18:20:34.479[sip]   Call-ID: 096407ed1506ff1302efa302527e76c4@192.168.100.90:5060
18:20:34.479[sip]   CSeq: 102 INVITE
18:20:34.479[sip]   Contact: <sip:1101@192.168.100.91:5060>
18:20:34.479[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33020174 sofia-sip/1.12.10
18:20:34.479[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
18:20:34.479[sip]   Require: timer
18:20:34.479[sip]   Supported: timer, 100rel, replaces
18:20:34.479[sip]   Session-Expires: 1800;refresher=uac
18:20:34.479[sip]   Min-SE: 120
18:20:34.479[sip]   Content-Type: application/sdp
18:20:34.479[sip]   Content-Disposition: session
18:20:34.479[sip]   Content-Length: 178
18:20:34.479[sip]
18:20:34.479[sip]   v=0
18:20:34.479[sip]   o=- 8651219803159688580 6772942873527236150 IN IP4 192.168.100.91
18:20:34.479[sip]   s=Session SDP
18:20:34.479[sip]   c=IN IP4 192.168.100.91
18:20:34.479[sip]   t=0 0
18:20:34.479[sip]   m=audio 23452 RTP/AVP 8
18:20:34.479[sip]   a=rtpmap:8 PCMA/8000
18:20:34.479[sip]   a=ptime:20
18:20:34.479[sip]   ------------------------------------------------------------------------
18:20:34.479[app:dbg]got nua_i_state : 200(OK)
18:20:34.479[app:dbg]NO SIP IN nua_i_state == 200 : OK
18:20:34.479[app:dbg]self_i_state(): call state 7: as : local sdp : sdp_init have_oc
18:20:34.479[sip]recv 405 bytes from udp/[192.168.100.90]:5060 at 01:51:10.260000:
18:20:34.479[sip]   ------------------------------------------------------------------------
18:20:34.479[sip]   ACK sip:1101@192.168.100.91:5060 SIP/2.0
18:20:34.479[sip]   Via: SIP/2.0/UDP 192.168.100.90:5060;branch=z9hG4bK0e0eb972
18:20:34.479[sip]   Max-Forwards: 70
18:20:34.479[sip]   From: "1102" <sip:1102@192.168.100.90>;tag=as67ebef54
18:20:34.479[sip]   To: <sip:1101@192.168.100.91:5060>;tag=Q18Zggcp4N4tg
18:20:34.479[sip]   Contact: <sip:1102@192.168.100.90:5060>
18:20:34.479[sip]   Call-ID: 096407ed1506ff1302efa302527e76c4@192.168.100.90:5060
18:20:34.479[sip]   CSeq: 102 ACK
18:20:34.479[sip]   User-Agent: FPBX-13.0.101(13.8.0)
18:20:34.479[sip]   Content-Length: 0
18:20:34.479[sip]
18:20:34.479[sip]   ------------------------------------------------------------------------
18:20:34.479[app:dbg]got nua_i_ack : 200(OK)
18:20:34.479[app:dbg]got nua_i_state : 200(OK)
18:20:34.479[app:dbg]NO SIP IN nua_i_state == 200 : OK
18:20:34.479[app:dbg]self_i_state(): call state 8: : : sdp_init have_oc
18:20:34.479[app:dbg]sip: call 02070017: ACK from sip:1102@192.168.100.90
18:20:34.479[app:dbg]sip: call 02070017: ACK from sip:1102@192.168.100.90
18:20:34.489[app:dbg]Port 7: user port 1, old state talking, new state
18:20:34.489[app:dbg]Set port 7 led to state 'LED_ON'
18:20:34.489[app:dbg]pbx -[msg_fxs_state]-> group
18:20:34.499[app:dbg]ITC: [msg_fxs_state] -> group
18:20:34.499[app:dbg]-----[GM] self_fxs_state()
18:20:34.499[app:dbg]Port 7: new state is talking
18:20:34.499[app:dbg]got nua_i_active : 200(Call active)
18:20:34.499[app:dbg]NO SIP IN nua_i_active == 200 : Call active
18:20:34.499[sip]recv 802 bytes from udp/[192.168.100.90]:5060 at 01:51:10.280000:
18:20:34.499[sip]   ------------------------------------------------------------------------
18:20:34.499[sip]   SIP/2.0 200 OK
18:20:34.499[sip]   Via: SIP/2.0/UDP 192.168.100.91;branch=z9hG4bK32Q4cteX1t7pc;received=192.168.100.91;rport=5060
18:20:34.499[sip]   From: "1102" <sip:1102@192.168.100.90>;tag=prF7eNUj7ce8m
18:20:34.499[sip]   To: <sip:1101@192.168.100.90>;tag=as33312270
18:20:34.499[sip]   Call-ID: c81db451-8002-1234-0a8d-a8f94b09c764
18:20:34.499[sip]   CSeq: 3333 INVITE
18:20:34.499[sip]   Server: FPBX-13.0.101(13.8.0)
18:20:34.499[sip]   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
18:20:34.499[sip]   Supported: replaces, timer
18:20:34.499[sip]   Session-Expires: 1800;refresher=uas
18:20:34.499[sip]   Contact: <sip:1101@192.168.100.90:5060>
18:20:34.499[sip]   Content-Type: application/sdp
18:20:34.499[sip]   Require: timer
18:20:34.499[sip]   Content-Length: 221
18:20:34.499[sip]
18:20:34.499[sip]   v=0
18:20:34.499[sip]   o=root 767463783 767463783 IN IP4 192.168.100.90
18:20:34.499[sip]   s=Asterisk PBX 13.8.0
18:20:34.499[sip]   c=IN IP4 192.168.100.90
18:20:34.499[sip]   t=0 0
18:20:34.499[sip]   m=audio 12868 RTP/AVP 0 8
18:20:34.499[sip]   a=rtpmap:0 PCMU/8000
18:20:34.499[sip]   a=rtpmap:8 PCMA/8000
18:20:34.499[sip]   a=ptime:20
18:20:34.499[sip]   a=maxptime:150
18:20:34.499[sip]   a=sendrecv
18:20:34.499[sip]   ------------------------------------------------------------------------
18:20:34.499[app:dbg]got nua_r_invite : 200(OK)
18:20:34.499[app:dbg]sip: call 00040019: INVITE: 200 OK
18:20:34.499[app:dbg]attr: name: ptime value: 20
18:20:34.499[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:20:34.509[app:dbg]attr: name: maxptime value: 150
18:20:34.509[app:dbg]sip: call 00040019: current status (200)
18:20:34.509[app:dbg]got nua_i_state : 200(OK)
18:20:34.509[app:dbg]NO SIP IN nua_i_state == 200 : OK
18:20:34.509[app:dbg]self_i_state(): call state 4: ar : remote sdp : sdp_sent have_oc
18:20:34.509[app:dbg]sip: call 00040019: SDP answer received
18:20:34.509[app:dbg]sip: call 00040019: calltype 1, mode_codec 0, codec 0
18:20:34.509[app:dbg]sip: call 00040019: SDP answer received
18:20:34.509[app:dbg]self_destroy_current_media() nothing to destroy
18:20:34.509[app:dbg]sdp_codecs_get_rfc2833: present=0 pt=101
18:20:34.509[app:WARN]update_call_rfc2833_sdp() no rfc2833 on local side - do not update from remote
18:20:34.509[app:dbg]self_start_media: 1. handle call id 0x00040019, call id 0x00040019
18:20:34.509[app:dbg]sip: set options: call 00040019: media stream 0: 192.168.100.91:23448 -> 192.168.100.90:12868: MFPT 0 <drop>
18:20:34.509[app:dbg]self_itc_codec(): payload 0
18:20:34.509[app:dbg]sip_set_rxtx_opts(): check rtpm <PCMU>:0
18:20:34.509[app:dbg]sip_set_rxtx_opts(): check offered 0: 8
18:20:34.509[app:dbg]sip_set_rxtx_opts(): check offered 1: 0
18:20:34.509[app:dbg]self_itc_codec(): payload 0
18:20:34.509[app:dbg]Supported codec[0]: <G.711U>:0, vbd off, vad on, ecan on
18:20:34.509[app:dbg]validate_ptime() codec G.711U, ptime 20, check_bigger 1, present 1
18:20:34.509[app:dbg]validate_ptime() using 20
18:20:34.509[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:20:34.509[app:dbg]sip_set_rxtx_opts(): check rtpm <PCMA>:8
18:20:34.509[app:dbg]sip_set_rxtx_opts(): check offered 0: 8
18:20:34.509[app:dbg]self_itc_codec(): payload 8
18:20:34.509[app:dbg]Supported codec[1]: <G.711A>:8, vbd off, vad on, ecan on
18:20:34.509[app:dbg]validate_ptime() codec G.711U, ptime 20, check_bigger 1, present 1
18:20:34.509[app:dbg]validate_ptime() using 20
18:20:34.509[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:20:34.509[app:dbg]sdp_codecs_get_rfc2833: present=0 pt=101
18:20:34.509[app:dbg]validate_ptime() codec G.711U, ptime 20, check_bigger 1, present 1
18:20:34.509[app:dbg]validate_ptime() using 20
18:20:34.509[app:dbg]sdp_codecs_set_ptime() ptime present : 20
18:20:34.509[app:dbg]self_start_media: 2. handle call id 0x00040019, call id 0x00040019
18:20:34.509[app:dbg]sip -[msg_set_media]-> pbx
18:20:34.509[app:dbg]sip: call 00040019: call answered
18:20:34.509[app:dbg]sip -[msg_answer]-> pbx
18:20:34.509[app:dbg]sip: call 00040019: ACK to sip:1101@192.168.100.90
18:20:34.509[app:dbg]got nua_r_set_params : 200(OK)
18:20:34.509[app:dbg]NO SIP IN nua_r_set_params == 200 : OK
18:20:34.509[sip]send 522 bytes to udp/[192.168.100.90]:5060 at 01:51:10.290000:
18:20:34.509[sip]   ------------------------------------------------------------------------
18:20:34.509[sip]   ACK sip:1101@192.168.100.90:5060 SIP/2.0
18:20:34.509[sip]   Via: SIP/2.0/UDP 192.168.100.91;rport;branch=z9hG4bK4BHXeNZ0y3X9Q
18:20:34.509[sip]   Max-Forwards: 70
18:20:34.509[sip]   From: "1102" <sip:1102@192.168.100.90>;tag=prF7eNUj7ce8m
18:20:34.509[sip]   To: <sip:1101@192.168.100.90>;tag=as33312270
18:20:34.509[sip]   Call-ID: c81db451-8002-1234-0a8d-a8f94b09c764
18:20:34.509[sip]   CSeq: 3333 ACK
18:20:34.509[sip]   Contact: <sip:1102@192.168.100.91:5060>
18:20:34.509[sip]   Authorization: Digest username="1102", realm="asterisk", nonce="79775b4e", algorithm=MD5, uri="sip:1101@192.168.100.90", response="da4e516fbed46020a1038f3f289112f1"
18:20:34.529[sip]   Content-Length: 0
18:20:34.529[sip]
18:20:34.529[sip]   ------------------------------------------------------------------------
18:20:34.529[app:dbg]got nua_i_state : 200(ACK sent)
18:20:34.529[app:dbg]NO SIP IN nua_i_state == 200 : ACK sent
18:20:34.529[app:dbg]self_i_state(): call state 8: : : sdp_init have_oc
18:20:34.529[app:dbg]sip: call 00040019: ACK from sip:1102@192.168.100.90
18:20:34.529[app:dbg]got nua_i_active : 200(Call active)
18:20:34.529[app:dbg]NO SIP IN nua_i_active == 200 : Call active
18:20:34.529[app:dbg]dump_port_calls() SLIC 7:
18:20:34.529[app:dbg]Q:(0x329800,0x02070017,(nil))
18:20:34.529[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:20:34.549[app:dbg]vapi_proc_event: VAPI_CB
18:20:34.549[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000923 result 0x00000000
18:20:34.549[app:dbg]Conn 7: Stop tone - Successfull
18:20:34.549[app:dbg]Port 7: check vapi queue ('busy''stop_tone') at vapi_next_ops:2532
18:20:34.559[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 7
18:20:34.569[app:dbg]ITC: [msg_set_media] -> pbx
18:20:34.569[app:dbg]self_on_set_media: call id 0x00040019 tx/rx 1/1
18:20:34.569[app:dbg]dump_port_calls() SLIC 4:
18:20:34.569[app:dbg]Q:(0x32a000,0x00040019,(nil))
18:20:34.569[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:20:34.569[app:dbg]SLIC 4: TX start / RX start: 192.168.100.91:23448->192.168.100.90:12868, <G.711U:0>
18:20:34.569[app:dbg]SLIC 4: send only 0 vad 1 g723_hr 1 vbd 0, ecan 1 rfc2833 pt -1, NSE pt 0, MFPT 0
18:20:34.569[app:dbg]self_set_media_start(): set ptime to 20
18:20:34.569[app:dbg]port_set_ip_param
18:20:34.569[app:dbg]set media param for '4', 192.168.100.91:23448, mode=local, random 8
18:20:34.569[app:dbg]port_set_ip_param
18:20:34.569[app:dbg]set media param for '4', 192.168.100.90:12868, mode=remote, random 8
18:20:34.569[app:dbg]CMD_CREATE_CONN: port = 4
18:20:34.569[app:dbg]Port 4: check vapi queue ('free') at vapi_create_chan:694
18:20:34.569[app:dbg]Chan 4: current state is CREATED
18:20:34.569[app:dbg]chan 4: no need to create - already exists
18:20:34.569[app:dbg]Port 4: check vapi queue ('free') at __cmd_engine:320
18:20:34.569[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2532
18:20:34.569[app:dbg]SLIC 4: starting media (G.711U) 192.168.100.91:23448 -> 192.168.100.90:12868
18:20:34.569[app:dbg]port 4: start voice - first time
18:20:34.569[app:dbg]port_start_voice() chan 04: remote IP <192.168.100.90> (arp query 0 times)
18:20:34.569[app:dbg]chan 4: get mac succesfull, repeat 0 times
18:20:34.569[app:dbg]CMD_START_VOICE: port = 4
18:20:34.569[app:dbg]vapi_set_chan_param: chan=4 hold=0 deactivate=0
18:20:34.569[app:dbg]Port 4: check vapi queue ('free') at vapi_set_chan_param:2136
18:20:34.569[app:dbg]Chan 4: current state is CREATED
18:20:34.569[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'start voice' at vapi_set_chan_param:2160
18:20:34.569[app:dbg]VQ Conn 4 = MSP :   'start voice' =
18:20:34.569[app:dbg]Conn 4 Eth src=a8:f9:4b:09:c7:64, dst=00:00:00:00:00:00
18:20:34.569[app:dbg]Conn 4 IP src=192.168.100.91:23448, dst=192.168.100.90:12868
18:20:34.569[app:dbg]CHECK REQID: 0x00000502(Conn 4)
18:20:34.569[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000502
18:20:34.569[app:dbg]vapi: Conn 4. Disable - Ok
18:20:34.569[app:dbg]vapi_proc_event: VAPI_CB
18:20:34.569[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000502 result 0x00000000
18:20:34.569[app:dbg]VOIP_DISABLE: chan = 4
18:20:34.569[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
18:20:34.569[app:dbg]vapi: create: TDM channel 4 Set SSRC to 5F1748A7
18:20:34.569[app:dbg]vapi: Conn 4. Set src/dst eth mac - Ok
18:20:34.569[app:dbg]Reserved IP: 192.168.253.1
18:20:34.569[app:dbg]vapi_cb_setchan: ch4. msp_ip = 192.168.253.2
18:20:34.569[app:dbg]IP PARAMS: 1FDA8C0 30448 2FDA8C0 30448
18:20:34.569[app:dbg]Create RX-TX media for SLIC 4(sendonly: 0, rtcp: 0)
18:20:34.569[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000508
18:20:34.569[app:dbg]vapi: Conn 4. Set src/dst ip addr - ok
18:20:34.579[app:dbg]ITC: [msg_answer] -> pbx
18:20:34.579[app:dbg]SLIC 4: peer answered
18:20:34.579[app:info]SLIC 4: from state 'ringback' to state 'talking'
18:20:34.579[app:dbg]CMD_STOP_TONE: port = 4
18:20:34.579[app:dbg]Port 4: check vapi queue ('busy''start voice') at vapi_stop_tone_chan:1474
18:20:34.579[app:dbg]Port 4 put cmd 'stop_tone',cur 'start voice' to queue at (vapi_stop_tone_chan:1480)
18:20:34.579[app:dbg]VQ Conn 4 = MSP :   'start voice' =
18:20:34.579[app:dbg]VQ Conn 4 + 04  :     'stop_tone'  + <-get_ptr
18:20:34.599[app:dbg]Port 4: user port 2, old state talking, new state
18:20:34.599[app:dbg]Set port 4 led to state 'LED_ON'
18:20:34.599[app:dbg]pbx -[msg_fxs_state]-> group
18:20:34.599[app:dbg]ITC: [msg_fxs_state] -> group
18:20:34.599[app:dbg]-----[GM] self_fxs_state()
18:20:34.599[app:dbg]Port 4: new state is talking
18:20:34.619[app:dbg]vapi_proc_event: VAPI_CB
18:20:34.619[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000508 result 0x00000000
18:20:34.619[app:dbg]VOIP_SET_IP: chan = 4
18:20:34.619[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
18:20:34.619[app:dbg]chan 4. vapi_cb_setchan: configure ecan on
18:20:34.619[app:dbg]vapi_passthru_echocan_cb() NLP, DCRF enabled, session 0, on 1, value 0x8007
18:20:34.619[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000547
18:20:34.629[app:dbg]vapi: generic event, code 5 <SSRC change>, conn 0
18:20:34.639[app:dbg]vapi_proc_event: VAPI_CB
18:20:34.639[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000547 result 0x00000000
18:20:34.639[app:dbg]VOIP_SSRC_FILT: chan = 4
18:20:34.639[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
18:20:34.639[app:dbg]chan 4. vapi_cb_setchan: VOIP_SSRC_FILT
18:20:34.639[app:dbg]vapi_cb_setchan: ch4. msp_ip = 192.168.253.2
18:20:34.639[app:dbg]RTCP IP PARAMS: 1FDA8C0 30449 2FDA8C0 30449
18:20:34.639[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000052b
18:20:34.649[app:dbg]vapi_proc_event: VAPI_CB
18:20:34.649[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000052b result 0x00000000
18:20:34.649[app:dbg]VOIP_SET_IP2: chan = 4
18:20:34.649[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
18:20:34.649[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PT
18:20:34.649[app:dbg]for chan <4> set codec type = 4 'G711U'
18:20:34.649[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000054e
18:20:34.659[app:dbg]vapi_proc_event: VAPI_CB
18:20:34.659[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000054e result 0x00000000
18:20:34.659[app:dbg]UNKNOWN_CMD: chan = 4
18:20:34.659[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
18:20:34.659[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_CODEC
18:20:34.659[app:dbg]set_packet_interval = 20
18:20:34.659[app:dbg]vapi: Conn 4. Set 'Packet interval' 20
18:20:34.659[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PACKET
18:20:34.659[app:dbg]SET TX PT: -1
18:20:34.659[app:dbg]vapi: Conn 4. Set DTMF PT as RFC: m_PT = 101
18:20:34.659[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PACKET2
18:20:34.659[app:dbg]SET RX PT: -1
18:20:34.659[app:dbg]vapi: Conn 4. Set DTMF PT as RFC: m_PT = 101
18:20:34.659[app:dbg]vapi: Chan 4 set chach (packet mode)
18:20:34.659[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_DTMFOPT dtmf 0, pt 101
18:20:34.659[app:dbg]Enable voice DTMF tones
18:20:34.659[app:dbg]Set RFC2833 PT: 101(01A5, 65FF)
18:20:34.659[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_DTMFOPT2
18:20:34.659[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_PT2
18:20:34.659[app:dbg]vapi: Conn 4. Enable RTP indication
18:20:34.659[app:dbg]chan 4. vapi_cb_setchan: VOIP_ENABLE_RTP_IND
18:20:34.659[app:dbg]chan 4: set jitter buffer options
18:20:34.659[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_INDCTL
18:20:34.659[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_JBOPT
18:20:34.659[app:dbg]vapi: Conn 4. Set tone ctl options
18:20:34.659[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_VLAN
18:20:34.659[app:dbg]VAD: 1 CNG: 0 PTE: 20
18:20:34.659[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000516
18:20:34.669[app:dbg]vapi_proc_event: VAPI_CB
18:20:34.669[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000516 result 0x00000000
18:20:34.669[app:dbg]VOIP_SET_VCEOPT: chan = 4
18:20:34.669[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
18:20:34.669[app:dbg]chan 4. vapi_cb_setchan: VOIP_SET_VCEOPT
18:20:34.669[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000518
18:20:34.679[app:dbg]vapi_proc_event: VAPI_CB
18:20:34.679[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000518 result 0x00000000
18:20:34.679[app:dbg]VOIP_SET_VOICE: chan = 4
18:20:34.679[app:dbg]vapi_cb_setchan: chan 4 deactivate 0
18:20:34.679[app:dbg]vapi_cb_setchan() Conn 4: set eActive state ok
18:20:34.679[app:dbg]Port 4: check vapi queue ('busy''start voice') at vapi_next_ops:2532
18:20:34.679[app:dbg]Port 4 get cmd 'stop_tone' from queue at (vapi_next_ops:2551)
18:20:34.679[app:dbg]Port 4: check vapi queue ('free') at vapi_stop_tone_chan:1474
18:20:34.679[app:dbg]Chan 4: current state is CREATED
18:20:34.679[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'stop_tone' at vapi_stop_tone_chan:1520
18:20:34.679[app:dbg]VQ Conn 4 = MSP :     'stop_tone' =
18:20:34.679[app:dbg]chan 4 stop tone
18:20:34.679[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000923
18:20:34.689[app:dbg]vapi_proc_event: VAPI_CB
18:20:34.689[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000923 result 0x00000000
18:20:34.689[app:dbg]Conn 4: Stop tone - Successfull
18:20:34.689[app:dbg]Port 4: check vapi queue ('busy''stop_tone') at vapi_next_ops:2532
18:20:34.699[app:dbg]vapi_proc_event: eVAPI_UNDEFINED_EVENT
18:20:34.699[app:dbg]vapi: Conn 7. event 'RTP Monitor Ind': Start RTP stream , PT 0x0008 'PCM-A', silence 0
18:20:34.709[app:dbg]vapi: generic event, code 5 <SSRC change>, conn 0
18:20:36.599[app:dbg]vapi_proc_event: eVAPI_UNDEFINED_EVENT
18:20:36.599[app:dbg]vapi: Conn 4. event 'RTP Monitor Ind': Start RTP stream , PT 0x0000 'PCM-U', silence 0
18:20:36.609[app:dbg]vapi: generic event, code 5 <SSRC change>, conn 0
18:20:36.789[app:dbg]slic7. Event 8.
18:20:36.789[app:dbg]slic 7. Pre-On-hook event
18:20:36.789[app:dbg]HIO: preonhook TDM port '7', port enabled 1
18:20:37.299[app:dbg]slic7. Event 1.
18:20:37.299[app:dbg]slic 7. On-hook event
18:20:37.299[app:dbg]Set port 7 led to state 'LED_OFF'
18:20:37.299[app:dbg]HIO: onhook TDM port '7', port enabled 1
18:20:37.299[app:dbg]SLIC 7 (1101): onhook state: talking
18:20:37.299[app:dbg]regex ID 7: dial reset
18:20:37.299[app:dbg]pbx -[msg_clear]-> sip
18:20:37.299[app:info]SLIC 7: from state 'talking' to state 'hangup'
18:20:37.299[app:dbg]ITC: [msg_clear] -> sip
18:20:37.299[app:dbg]call 02070017,flags(00000048): endpoint 7 cleared
18:20:37.299[app:dbg]sip: call 02070017: BYE to sip:1101@192.168.100.91:5060
18:20:37.299[sip]send 681 bytes to udp/[192.168.100.90]:5060 at 01:51:13.080000:
18:20:37.299[sip]   ------------------------------------------------------------------------
18:20:37.299[sip]   BYE sip:1102@192.168.100.90:5060 SIP/2.0
18:20:37.299[sip]   Via: SIP/2.0/UDP 192.168.100.91;rport;branch=z9hG4bK5mapggg4UcmvK
18:20:37.299[sip]   Max-Forwards: 70
18:20:37.299[sip]   From: <sip:1101@192.168.100.91:5060>;tag=Q18Zggcp4N4tg
18:20:37.299[sip]   To: "1102" <sip:1102@192.168.100.90>;tag=as67ebef54
18:20:37.299[sip]   Call-ID: 096407ed1506ff1302efa302527e76c4@192.168.100.90:5060
18:20:37.299[sip]   CSeq: 3336 BYE
18:20:37.299[sip]   Contact: <sip:1101@192.168.100.91:5060>
18:20:37.299[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33020174 sofia-sip/1.12.10
18:20:37.299[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
18:20:37.299[sip]   Supported: timer, 100rel, replaces
18:20:37.299[sip]   Reason: Q.850;cause=16;text="Normal call clearing"
18:20:37.299[sip]   Content-Length: 0
18:20:37.299[sip]   P-RTP-Stat: PS=66, OS=10716, PR=58, OR=9976, PL=0, JI=10
18:20:37.299[sip]
18:20:37.299[sip]   ------------------------------------------------------------------------
18:20:37.299[sip]recv 472 bytes from udp/[192.168.100.90]:5060 at 01:51:13.080000:
18:20:37.299[sip]   ------------------------------------------------------------------------
18:20:37.299[sip]   SIP/2.0 200 OK
18:20:37.299[sip]   Via: SIP/2.0/UDP 192.168.100.91;branch=z9hG4bK5mapggg4UcmvK;received=192.168.100.91;rport=5060
18:20:37.299[sip]   From: <sip:1101@192.168.100.91:5060>;tag=Q18Zggcp4N4tg
18:20:37.319[sip]   To: "1102" <sip:1102@192.168.100.90>;tag=as67ebef54
18:20:37.319[sip]   Call-ID: 096407ed1506ff1302efa302527e76c4@192.168.100.90:5060
18:20:37.319[sip]   CSeq: 3336 BYE
18:20:37.319[sip]   Server: FPBX-13.0.101(13.8.0)
18:20:37.319[sip]   Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
18:20:37.319[sip]   Supported: replaces, timer
18:20:37.319[sip]   Content-Length: 0
18:20:37.319[sip]
18:20:37.319[sip]   ------------------------------------------------------------------------
18:20:37.319[app:dbg]got nua_r_bye : 200(OK)
18:20:37.319[app:dbg]sip: call 02070017: BYE/INFO: 200 OK
18:20:37.319[app:dbg]got nua_i_state : 200(to BYE)
18:20:37.319[app:dbg]NO SIP IN nua_i_state == 200 : to BYE
18:20:37.319[app:dbg]self_i_state(): call state 10: : : sdp_init have_oc
18:20:37.319[app:dbg]sip: call 02070017: terminated
18:20:37.319[app:dbg]self_callstate_terminated: call id = 02070017 need_exchange_at_answer = 0
18:20:37.319[sip]recv 589 bytes from udp/[192.168.100.90]:5060 at 01:51:13.100000:
18:20:37.319[sip]   ------------------------------------------------------------------------
18:20:37.319[sip]   BYE sip:1102@192.168.100.91:5060 SIP/2.0
18:20:37.319[sip]   Via: SIP/2.0/UDP 192.168.100.90:5060;branch=z9hG4bK7bdaeef2;rport
18:20:37.319[sip]   Max-Forwards: 70
18:20:37.319[sip]   From: <sip:1101@192.168.100.90>;tag=as33312270
18:20:37.319[sip]   To: "1102" <sip:1102@192.168.100.90>;tag=prF7eNUj7ce8m
18:20:37.319[sip]   Call-ID: c81db451-8002-1234-0a8d-a8f94b09c764
18:20:37.319[sip]   CSeq: 102 BYE
18:20:37.319[sip]   User-Agent: FPBX-13.0.101(13.8.0)
18:20:37.319[sip]   Proxy-Authorization: Digest username="1102", realm="asterisk", algorithm=MD5, uri="sip:192.168.100.90", nonce="79775b4e", response="cb0bc49fdf79c00cc2106ee23c61e878"
18:20:37.319[sip]   X-Asterisk-HangupCause: Normal Clearing
18:20:37.319[sip]   X-Asterisk-HangupCauseCode: 16
18:20:37.319[sip]   Content-Length: 0
18:20:37.319[sip]
18:20:37.319[sip]   ------------------------------------------------------------------------
18:20:37.319[app:dbg]got nua_i_bye : 100(Trying)
18:20:37.319[sip]send 523 bytes to udp/[192.168.100.90]:5060 at 01:51:13.100000:
18:20:37.319[sip]   ------------------------------------------------------------------------
18:20:37.319[sip]   SIP/2.0 200 OK
18:20:37.329[app:dbg]CMD_STOP_TONE: port = 7
18:20:37.329[app:dbg]Port 7: check vapi queue ('free') at vapi_stop_tone_chan:1474
18:20:37.329[app:dbg]Chan 7: current state is CREATED
18:20:37.329[app:ERR]chan 7: no generated tones!
18:20:37.329[app:dbg]vapi_chan.c:1510: conn 7 peek cmd 'no event' from queue
18:20:37.329[app:dbg]Port 7: check vapi queue ('free') at __cmd_engine:320
18:20:37.329[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2532
18:20:37.329[app:dbg]SLIC 7: reset
18:20:37.329[app:dbg]dump_port_calls() SLIC 7:
18:20:37.329[app:dbg]Q:(0x329800,0x02070017,(nil))
18:20:37.329[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:20:37.329[app:dbg]vapi: chan 7: connection STATISTIC
18:20:37.329[app:dbg]vapi: chan 7: Rx_pack = 83
18:20:37.329[app:dbg]vapi: chan 7: Rx_oct  = 14276
18:20:37.329[app:dbg]vapi: chan 7: Lost_pack  = 0
18:20:37.329[app:dbg]vapi: chan 7: Tx_pack = 83
18:20:37.329[app:dbg]vapi: chan 7: Tx_oct  = 13004
18:20:37.329[app:dbg]vapi: chan 7: peak_jiter = 10
18:20:37.329[app:dbg]SLIC 7: Common port statistic
18:20:37.329[app:dbg]SLIC 7: Rx_pack = 18464
18:20:37.329[app:dbg]SLIC 7: Rx_oct  = 3175808
18:20:37.329[app:dbg]SLIC 7: Lost_pack  = 0
18:20:37.319[sip]   Via: SIP/2.0/UDP 192.168.100.90:5060;branch=z9hG4bK7bdaeef2;rport=5060
18:20:37.339[app:dbg]SLIC 7: Tx_pack = 34319
18:20:37.339[app:dbg]SLIC 7: Tx_oct  = 5604902
18:20:37.339[app:dbg]SLIC 7: peak_jiter = 10
18:20:37.339[app:dbg]SLIC 7: reset call 0x02070017 (active)
18:20:37.339[app:dbg]CMD_SET_VOICE: port = 7
18:20:37.339[app:dbg]Port 7: check vapi queue ('free') at vapi_start_stop_chan:1623
18:20:37.339[app:dbg]Chan 7: current state is CREATED
18:20:37.339[app:dbg]vapi: Conn 7. start_stop voice chan, TX stop, RX stop
18:20:37.339[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'set voice' at vapi_start_stop_chan:1666
18:20:37.339[app:dbg]VQ Conn 7 = MSP :     'set voice' =
18:20:37.339[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000401
18:20:37.339[app:dbg]incom_calls_set_media_started() call 0x02070017, group -1, task <sip> media stopped
18:20:37.349[sip]   From: <sip:1101@192.168.100.90>;tag=as33312270
18:20:37.349[sip]   To: "1102" <sip:1102@192.168.100.90>;tag=prF7eNUj7ce8m
18:20:37.349[sip]   Call-ID: c81db451-8002-1234-0a8d-a8f94b09c764
18:20:37.349[sip]   CSeq: 102 BYE
18:20:37.349[sip]   User-Agent: TAU-8.IP/2.0.0 SN/VI33020174 sofia-sip/1.12.10
18:20:37.349[sip]   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, INFO
18:20:37.349[sip]   Supported: timer, 100rel, replaces
18:20:37.349[sip]   Content-Length: 0
18:20:37.349[sip]   P-RTP-Stat: PS=55, OS=8824, PR=3, OR=516, PL=0, JI=0
18:20:37.349[sip]
18:20:37.349[sip]   ------------------------------------------------------------------------
18:20:37.349[app:dbg]got nua_i_state : 200(Session Terminated)
18:20:37.349[app:dbg]NO SIP IN nua_i_state == 200 : Session Terminated
18:20:37.349[app:dbg]self_i_state(): call state 10: : : sdp_init have_oc
18:20:37.349[app:dbg]sip: call 00040019: terminated
18:20:37.349[app:dbg]7011: endpoint 4 set to busy
18:20:37.349[app:dbg]sip -[msg_clear]-> pbx
18:20:37.349[app:dbg]self_callstate_terminated: call id = 00040019 need_exchange_at_answer = 0
18:20:37.359[app:dbg]incom_calls_rem() rem call 0x02070017, group -1, task <sip> from list
18:20:37.359[app:dbg]free_final_mx: final_mx was NULL for SLIC 7
18:20:37.359[app:dbg]CMD_DESTROY_CONN: port = 7
18:20:37.359[app:dbg]Port 7: check vapi queue ('busy''set voice') at vapi_destroy_chan:890
18:20:37.359[app:dbg]Clear vapi queue of Port 7/chan 7
18:20:37.359[app:dbg]Port 7 put cmd 'destroy',cur 'set voice' to queue at (vapi_destroy_chan:897)
18:20:37.359[app:dbg]VQ Conn 7 = MSP :     'set voice' =
18:20:37.359[app:dbg]VQ Conn 7 + 00  :       'destroy'  + <-get_ptr
18:20:37.359[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 7
18:20:37.359[app:dbg]Port 7: check vapi queue ('busy''set voice') at vapi_destroy_chan:890
18:20:37.359[app:dbg]Clear vapi queue of Port 7/chan 15
18:20:37.359[app:dbg]Port 7 put cmd 'destroy',cur 'set voice' to queue at (vapi_destroy_chan:897)
18:20:37.359[app:dbg]VQ Conn 15 = MSP :     'set voice' =
18:20:37.359[app:dbg]VQ Conn 15 + 00  :       'destroy'  + <-get_ptr
18:20:37.359[app:dbg]VQ Conn 15 + 01  :       'destroy' (hold) +
18:20:37.359[app:dbg]Port 7: user port 1, old state hangup, new state
18:20:37.359[app:dbg]Set port 7 led to state 'LED_OFF'
18:20:37.359[app:dbg]pbx -[msg_fxs_state]-> group
18:20:37.369[app:dbg]Delete all RX-TX medias from SLIC 7
18:20:37.369[app:dbg]ITC: [msg_fxs_state] -> group
18:20:37.369[app:dbg]-----[GM] self_fxs_state()
18:20:37.369[app:dbg]Port 7: new state is hangup
18:20:37.379[app:dbg]Delete all RX-TX medias from SLIC 15
18:20:37.379[app:dbg]dump_port_calls() SLIC 7:
18:20:37.379[app:dbg]Q:NONE
18:20:37.379[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:20:37.379[app:dbg]Set port 7 led to state 'LED_OFF'
18:20:37.399[app:dbg]vapi_proc_event: VAPI_CB
18:20:37.399[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000401 result 0x00000000
18:20:37.399[app:dbg]vapi: conn 7. RTCP disabled
18:20:37.399[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x000004ff
18:20:37.409[app:dbg]ITC: [msg_clear] -> pbx
18:20:37.409[app:dbg]dump_port_calls() SLIC 4:
18:20:37.409[app:dbg]Q:(0x32a000,0x00040019,(nil))
18:20:37.409[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:20:37.409[app:dbg]SLIC 4: peer cleared(00040019)
18:20:37.409[app:dbg]SLIC 4: current call cleared
18:20:37.409[app:dbg]SLIC 4: -> busy - no hold call, no wait call
18:20:37.409[app:info]SLIC 4: from state 'talking' to state 'busy'
18:20:37.419[app:dbg]port_start_tone(4 22 0 0)
18:20:37.419[app:dbg]CMD_START_TONE: port = 4
18:20:37.419[app:dbg]Port 4: check vapi queue ('free') at vapi_start_tone_chan:1384
18:20:37.429[app:dbg]Chan 4: current state is CREATED
18:20:37.429[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'start_tone' at vapi_start_tone_chan:1421
18:20:37.429[app:dbg]VQ Conn 4 = MSP :    'start_tone' =
18:20:37.429[app:dbg]chan 4 start tone, id=22, direction=TDM
18:20:37.429[app:dbg]Port 4: user port 2, old state busy, new state
18:20:37.429[app:dbg]Set port 4 led to state 'LED_ON'
18:20:37.429[app:dbg]pbx -[msg_fxs_state]-> group
18:20:37.429[app:dbg]ITC: [msg_fxs_state] -> group
18:20:37.429[app:dbg]-----[GM] self_fxs_state()
18:20:37.429[app:dbg]Port 4: new state is busy
18:20:37.439[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000922
18:20:37.449[app:dbg]vapi: chan 4: connection STATISTIC
18:20:37.449[app:dbg]vapi: chan 4: Rx_pack = 16
18:20:37.449[app:dbg]vapi: chan 4: Rx_oct  = 2752
18:20:37.449[app:dbg]vapi: chan 4: Lost_pack  = 0
18:20:37.449[app:dbg]vapi: chan 4: Tx_pack = 88
18:20:37.449[app:dbg]vapi: chan 4: Tx_oct  = 13705
18:20:37.449[app:dbg]vapi: chan 4: peak_jiter = 0
18:20:37.449[app:dbg]SLIC 4: Common port statistic
18:20:37.449[app:dbg]SLIC 4: Rx_pack = 30111
18:20:37.449[app:dbg]SLIC 4: Rx_oct  = 5179092
18:20:37.449[app:dbg]SLIC 4: Lost_pack  = 0
18:20:37.449[app:dbg]SLIC 4: Tx_pack = 23411
18:20:37.449[app:dbg]SLIC 4: Tx_oct  = 3593258
18:20:37.449[app:dbg]SLIC 4: peak_jiter = 0
18:20:37.449[app:dbg]SLIC 4: reset call 0x00040019 (active)
18:20:37.449[app:dbg]CMD_SET_VOICE: port = 4
18:20:37.449[app:dbg]Port 4: check vapi queue ('busy''start_tone') at vapi_start_stop_chan:1623
18:20:37.449[app:dbg]Port 4 put cmd 'set voice',cur 'start_tone' to queue at (vapi_start_stop_chan:1630)
18:20:37.449[app:dbg]VQ Conn 4 = MSP :    'start_tone' =
18:20:37.449[app:dbg]VQ Conn 4 + 05  :     'set voice'  + <-get_ptr
18:20:37.469[app:dbg]dump_port_calls() SLIC 4:
18:20:37.469[app:dbg]Q:NONE
18:20:37.469[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:20:37.469[app:dbg]vapi_proc_event: VAPI_CB
18:20:37.469[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x000004ff result 0x00000000
18:20:37.469[app:dbg]Conn 7: Set voice mode successeful
18:20:37.469[app:dbg]Stop all medias on chan 7
18:20:37.469[app:dbg]Port 7: check vapi queue ('busy''set voice') at vapi_next_ops:2532
18:20:37.469[app:dbg]Port 7 get cmd 'destroy' from queue at (vapi_next_ops:2551)
18:20:37.469[app:dbg]VQ Conn 7 + 01  :       'destroy' (hold) + <-get_ptr
18:20:37.469[app:dbg]Port 7: check vapi queue ('free') at vapi_destroy_chan:890
18:20:37.469[app:dbg]Destroying connection 7...
18:20:37.469[app:dbg]Chan 7: current state is CREATED
18:20:37.469[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'destroy' at vapi_destroy_chan:916
18:20:37.469[app:dbg]VQ Conn 7 = MSP :       'destroy' =
18:20:37.469[app:dbg]VQ Conn 7 + 01  :       'destroy' (hold) + <-get_ptr
18:20:37.469[app:dbg]Chan 7: CREATED -> DESTROYING
18:20:37.469[app:dbg]slic7. Event 2.
18:20:37.469[app:dbg]slic 7. Off-hook event
18:20:37.469[app:dbg]Set port 7 led to state 'LED_ON'
18:20:37.469[app:dbg]HIO: offhook TDM port '7' port enabled 1
18:20:37.469[app:dbg]HIO: offhook TDM port '7' direction unknown -> outgoing
18:20:37.469[app:dbg]SLIC 7 (1101): offhook state: hangup
18:20:37.469[app:dbg]regex ID 7: dial reset
18:20:37.469[app:info]SLIC 7: from state 'hangup' to state 'hangdown'
18:20:37.469[app:dbg]CMD_CREATE_CONN: port = 7
18:20:37.469[app:dbg]Port 7: check vapi queue ('busy''destroy') at vapi_create_chan:694
18:20:37.469[app:dbg]Port 7 put cmd 'create',cur 'destroy' to queue at (vapi_create_chan:700)
18:20:37.469[app:dbg]VQ Conn 7 = MSP :       'destroy' =
18:20:37.469[app:dbg]VQ Conn 7 + 01  :       'destroy' (hold) + <-get_ptr
18:20:37.469[app:dbg]VQ Conn 7 + 02  :        'create'  +
18:20:37.469[app:dbg]CMD_CREATE_CONN: port = 7
18:20:37.469[app:dbg]Port 7: check vapi queue ('busy''destroy') at vapi_create_chan:694
18:20:37.469[app:dbg]Port 7 put cmd 'create',cur 'destroy' to queue at (vapi_create_chan:700)
18:20:37.469[app:dbg]VQ Conn 7 = MSP :       'destroy' =
18:20:37.469[app:dbg]VQ Conn 7 + 01  :       'destroy' (hold) + <-get_ptr
18:20:37.469[app:dbg]VQ Conn 7 + 02  :        'create'  +
18:20:37.469[app:dbg]VQ Conn 7 + 03  :        'create'  +
18:20:37.469[app:dbg]port_start_tone(7 21 0 0)
18:20:37.469[app:dbg]CMD_START_TONE: port = 7
18:20:37.469[app:dbg]Port 7: check vapi queue ('busy''destroy') at vapi_start_tone_chan:1384
18:20:37.469[app:dbg]Port 7 put cmd 'start_tone',cur 'destroy' to queue at (vapi_start_tone_chan:1394)
18:20:37.469[app:dbg]VQ Conn 7 = MSP :       'destroy' =
18:20:37.469[app:dbg]VQ Conn 7 + 01  :       'destroy' (hold) + <-get_ptr
18:20:37.469[app:dbg]VQ Conn 7 + 02  :        'create'  +
18:20:37.469[app:dbg]VQ Conn 7 + 03  :        'create'  +
18:20:37.469[app:dbg]VQ Conn 7 + 04  :    'start_tone'  +
18:20:37.469[app:dbg]Port 7: user port 1, old state hangdown, new state
18:20:37.469[app:dbg]Set port 7 led to state 'LED_ON'
18:20:37.469[app:dbg]pbx -[msg_fxs_state]-> group
18:20:37.479[app:dbg]Delete all RX-TX medias from SLIC 4
18:20:37.479[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x0000014b
18:20:37.479[app:dbg]ITC: [msg_fxs_state] -> group
18:20:37.479[app:dbg]-----[GM] self_fxs_state()
18:20:37.479[app:dbg]Port 7: new state is hangdown
18:20:37.489[app:dbg]Mute all RX-TX medias on SLIC 7
18:20:37.499[app:dbg]Delete all RX-TX medias from SLIC 7
18:20:37.499[app:info]Looking for hot numbers
18:20:37.499[app:dbg]dump_port_calls() SLIC 7:
18:20:37.499[app:dbg]Q:NONE
18:20:37.499[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:20:37.509[app:dbg]vapi_proc_event: VAPI_CB
18:20:37.509[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000922 result 0x00000000
18:20:37.509[app:dbg]Conn 4: Start tone - Successfull
18:20:37.509[app:dbg]Port 4: check vapi queue ('busy''start_tone') at vapi_next_ops:2532
18:20:37.509[app:dbg]Port 4 get cmd 'set voice' from queue at (vapi_next_ops:2551)
18:20:37.509[app:dbg]Port 4: check vapi queue ('free') at vapi_start_stop_chan:1623
18:20:37.509[app:dbg]Chan 4: current state is CREATED
18:20:37.509[app:dbg]vapi: Conn 4. start_stop voice chan, TX stop, RX stop
18:20:37.509[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'set voice' at vapi_start_stop_chan:1666
18:20:37.509[app:dbg]VQ Conn 4 = MSP :     'set voice' =
18:20:37.509[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000401
18:20:37.519[app:dbg]vapi_proc_event: VAPI_CB
18:20:37.519[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x0000014b result 0x00000000
18:20:37.519[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000103
18:20:37.529[app:dbg]vapi_proc_event: VAPI_CB
18:20:37.529[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000401 result 0x00000000
18:20:37.529[app:dbg]vapi: conn 4. RTCP disabled
18:20:37.529[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x000004ff
18:20:37.539[app:dbg]vapi_proc_event: VAPI_CB
18:20:37.539[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000103 result 0x00000000
18:20:37.539[app:dbg]Conn 7 destroyed
18:20:37.539[app:dbg]Chan 7: DESTROYING -> INITIAL
18:20:37.539[app:dbg]Port 7: check vapi queue ('busy''destroy') at vapi_next_ops:2532
18:20:37.539[app:dbg]Port 7 get cmd 'destroy' from queue at (vapi_next_ops:2551)
18:20:37.539[app:dbg]VQ Conn 7 + 02  :        'create'  + <-get_ptr
18:20:37.539[app:dbg]VQ Conn 7 + 03  :        'create'  +
18:20:37.539[app:dbg]VQ Conn 7 + 04  :    'start_tone'  +
18:20:37.539[app:dbg]Port 7: check vapi queue ('free') at vapi_destroy_chan:890
18:20:37.539[app:dbg]Destroying connection 15...
18:20:37.539[app:dbg]Chan 15: current state is INITIAL
18:20:37.539[app:ERR]vapi_destroy_chan() chan 15: current state initial: duplicate destroying connection!
18:20:37.539[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2694
18:20:37.539[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2532
18:20:37.539[app:dbg]Port 7 get cmd 'create' from queue at (vapi_next_ops:2551)
18:20:37.539[app:dbg]VQ Conn 7 + 03  :        'create'  + <-get_ptr
18:20:37.539[app:dbg]VQ Conn 7 + 04  :    'start_tone'  +
18:20:37.539[app:dbg]Port 7: check vapi queue ('free') at vapi_create_chan:694
18:20:37.539[app:dbg]Chan 7: current state is INITIAL
18:20:37.539[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'create' at vapi_create_chan:720
18:20:37.539[app:dbg]VQ Conn 7 = MSP :        'create' =
18:20:37.539[app:dbg]VQ Conn 7 + 03  :        'create'  + <-get_ptr
18:20:37.539[app:dbg]VQ Conn 7 + 04  :    'start_tone'  +
18:20:37.539[app:dbg]Creating connection 7....
18:20:37.539[app:dbg]Chan 7: INITIAL -> CREATING
18:20:37.539[app:dbg]Created succefuly 7....
18:20:37.539[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x0000004f
18:20:37.549[app:dbg]vapi_proc_event: VAPI_CB
18:20:37.549[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x000004ff result 0x00000000
18:20:37.549[app:dbg]Conn 4: Set voice mode successeful
18:20:37.549[app:dbg]Stop all medias on chan 4
18:20:37.549[app:dbg]Port 4: check vapi queue ('busy''set voice') at vapi_next_ops:2532
18:20:37.549[app:dbg]Mute all RX-TX medias on SLIC 4
18:20:37.559[app:dbg]vapi_proc_event: VAPI_CB
18:20:37.559[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x0000004f result 0x00000000
18:20:37.559[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000000
18:20:37.569[app:dbg]vapi_proc_event: VAPI_CB
18:20:37.569[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000000 result 0x00000000
18:20:37.569[app:dbg]vapi: Conn 7 - << CREATED >>
18:20:37.569[app:dbg]vapi: Conn 7 - fix DTMF detector
18:20:37.569[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000049
18:20:37.579[app:dbg]vapi_proc_event: VAPI_CB
18:20:37.579[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000049 result 0x00000000
18:20:37.579[app:dbg]vapi: Conn 7 - fix CNG generator
18:20:37.579[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x0000004c
18:20:37.589[app:dbg]vapi_proc_event: VAPI_CB
18:20:37.589[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x0000004c result 0x00000000
18:20:37.589[app:dbg]vapi: Conn 7 - caller id Set param
18:20:37.589[app:dbg]vapi: chan '7' set param Caller ID
18:20:37.589[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x0000000c
18:20:37.599[app:dbg]vapi_proc_event: VAPI_CB
18:20:37.599[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x0000000c result 0x00000000
18:20:37.599[app:dbg]vapi: Conn 7 - enable ind ptime and pt
18:20:37.599[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x0000004a
18:20:37.609[app:dbg]vapi_proc_event: VAPI_CB
18:20:37.609[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x0000004a result 0x00000000
18:20:37.609[app:dbg]Chan 7: CREATING -> CREATED
18:20:37.609[app:dbg]Port 7: check vapi queue ('busy''create') at vapi_next_ops:2532
18:20:37.609[app:dbg]Port 7 get cmd 'create' from queue at (vapi_next_ops:2551)
18:20:37.609[app:dbg]VQ Conn 7 + 04  :    'start_tone'  + <-get_ptr
18:20:37.609[app:dbg]Port 7: check vapi queue ('free') at vapi_create_chan:694
18:20:37.609[app:dbg]Chan 7: current state is CREATED
18:20:37.609[app:dbg]chan 7: no need to create - already exists
18:20:37.609[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2694
18:20:37.609[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2532
18:20:37.609[app:dbg]Port 7 get cmd 'start_tone' from queue at (vapi_next_ops:2551)
18:20:37.609[app:dbg]Port 7: check vapi queue ('free') at vapi_start_tone_chan:1384
18:20:37.609[app:dbg]Chan 7: current state is CREATED
18:20:37.609[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'start_tone' at vapi_start_tone_chan:1421
18:20:37.609[app:dbg]VQ Conn 7 = MSP :    'start_tone' =
18:20:37.609[app:dbg]chan 7 start tone, id=21, direction=TDM
18:20:37.609[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000922
18:20:37.619[app:dbg]vapi_proc_event: VAPI_CB
18:20:37.619[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000922 result 0x00000000
18:20:37.619[app:dbg]Conn 7: Start tone - Successfull
18:20:37.619[app:dbg]Port 7: check vapi queue ('busy''start_tone') at vapi_next_ops:2532
18:20:39.969[app:dbg]slic7. Event 8.
18:20:39.969[app:dbg]slic 7. Pre-On-hook event
18:20:39.969[app:dbg]HIO: preonhook TDM port '7', port enabled 1
18:20:39.969[app:dbg]CMD_STOP_TONE: port = 7
18:20:39.969[app:dbg]Port 7: check vapi queue ('free') at vapi_stop_tone_chan:1474
18:20:39.969[app:dbg]Chan 7: current state is CREATED
18:20:39.969[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'stop_tone' at vapi_stop_tone_chan:1520
18:20:39.969[app:dbg]VQ Conn 7 = MSP :     'stop_tone' =
18:20:39.969[app:dbg]chan 7 stop tone
18:20:39.969[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000923
18:20:39.979[app:dbg]vapi_proc_event: VAPI_CB
18:20:39.979[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000923 result 0x00000000
18:20:39.979[app:dbg]Conn 7: Stop tone - Successfull
18:20:39.979[app:dbg]Port 7: check vapi queue ('busy''stop_tone') at vapi_next_ops:2532
18:20:39.989[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 7
18:20:40.469[app:dbg]slic7. Event 1.
18:20:40.469[app:dbg]slic 7. On-hook event
18:20:40.469[app:dbg]Set port 7 led to state 'LED_OFF'
18:20:40.469[app:dbg]HIO: onhook TDM port '7', port enabled 1
18:20:40.469[app:dbg]SLIC 7 (1101): onhook state: hangdown
18:20:40.469[app:dbg]regex ID 7: dial reset
18:20:40.479[app:info]SLIC 7: from state 'hangdown' to state 'hangup'
18:20:40.479[app:dbg]CMD_STOP_TONE: port = 7
18:20:40.479[app:dbg]Port 7: check vapi queue ('free') at vapi_stop_tone_chan:1474
18:20:40.479[app:dbg]Chan 7: current state is CREATED
18:20:40.479[app:ERR]chan 7: no generated tones!
18:20:40.479[app:dbg]vapi_chan.c:1510: conn 7 peek cmd 'no event' from queue
18:20:40.479[app:dbg]Port 7: check vapi queue ('free') at __cmd_engine:320
18:20:40.479[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2532
18:20:40.479[app:dbg]SLIC 7: reset
18:20:40.479[app:dbg]dump_port_calls() SLIC 7:
18:20:40.479[app:dbg]Q:NONE
18:20:40.479[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:20:40.479[app:dbg]free_final_mx: final_mx was NULL for SLIC 7
18:20:40.489[app:dbg]CMD_DESTROY_CONN: port = 7
18:20:40.489[app:dbg]Port 7: check vapi queue ('free') at vapi_destroy_chan:890
18:20:40.489[app:dbg]Destroying connection 7...
18:20:40.489[app:dbg]Chan 7: current state is CREATED
18:20:40.489[app:dbg]Port 7: set vapi queue MSP to 'busy' with 'destroy' at vapi_destroy_chan:916
18:20:40.489[app:dbg]VQ Conn 7 = MSP :       'destroy' =
18:20:40.489[app:dbg]Chan 7: CREATED -> DESTROYING
18:20:40.489[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 7
18:20:40.489[app:dbg]Port 7: check vapi queue ('busy''destroy') at vapi_destroy_chan:890
18:20:40.489[app:dbg]Clear vapi queue of Port 7/chan 15
18:20:40.489[app:dbg]Port 7 put cmd 'destroy',cur 'destroy' to queue at (vapi_destroy_chan:897)
18:20:40.489[app:dbg]VQ Conn 15 = MSP :       'destroy' =
18:20:40.489[app:dbg]VQ Conn 15 + 00  :       'destroy' (hold) + <-get_ptr
18:20:40.489[app:dbg]Port 7: user port 1, old state hangup, new state
18:20:40.489[app:dbg]Set port 7 led to state 'LED_OFF'
18:20:40.489[app:dbg]pbx -[msg_fxs_state]-> group
18:20:40.489[app:dbg]ITC: [msg_fxs_state] -> group
18:20:40.489[app:dbg]-----[GM] self_fxs_state()
18:20:40.489[app:dbg]Port 7: new state is hangup
18:20:40.489[app:dbg]Delete all RX-TX medias from SLIC 7
18:20:40.499[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x0000014b
18:20:40.509[app:dbg]Delete all RX-TX medias from SLIC 15
18:20:40.509[app:dbg]dump_port_calls() SLIC 7:
18:20:40.509[app:dbg]Q:NONE
18:20:40.509[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:20:40.509[app:dbg]Set port 7 led to state 'LED_OFF'
18:20:40.519[app:dbg]Delete all RX-TX medias from SLIC 7
18:20:40.519[app:dbg]vapi_proc_event: VAPI_CB
18:20:40.519[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x0000014b result 0x00000000
18:20:40.519[app:dbg]vapi_cb_req: 7 0 result 0x00000000 requid 0x00000103
18:20:40.529[app:dbg]vapi_proc_event: VAPI_CB
18:20:40.529[app:dbg]vapi_cb_chan: chan 7 reqest_id 0x00000103 result 0x00000000
18:20:40.529[app:dbg]Conn 7 destroyed
18:20:40.529[app:dbg]Chan 7: DESTROYING -> INITIAL
18:20:40.529[app:dbg]Port 7: check vapi queue ('busy''destroy') at vapi_next_ops:2532
18:20:40.529[app:dbg]Port 7 get cmd 'destroy' from queue at (vapi_next_ops:2551)
18:20:40.529[app:dbg]Port 7: check vapi queue ('free') at vapi_destroy_chan:890
18:20:40.529[app:dbg]Destroying connection 15...
18:20:40.529[app:dbg]Chan 15: current state is INITIAL
18:20:40.529[app:ERR]vapi_destroy_chan() chan 15: current state initial: duplicate destroying connection!
18:20:40.529[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2694
18:20:40.529[app:dbg]Port 7: check vapi queue ('free') at vapi_next_ops:2532
18:20:40.859[app:dbg]slic4. Event 8.
18:20:40.859[app:dbg]slic 4. Pre-On-hook event
18:20:40.859[app:dbg]HIO: preonhook TDM port '4', port enabled 1
18:20:40.859[app:dbg]CMD_STOP_TONE: port = 4
18:20:40.859[app:dbg]Port 4: check vapi queue ('free') at vapi_stop_tone_chan:1474
18:20:40.859[app:dbg]Chan 4: current state is CREATED
18:20:40.859[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'stop_tone' at vapi_stop_tone_chan:1520
18:20:40.859[app:dbg]VQ Conn 4 = MSP :     'stop_tone' =
18:20:40.859[app:dbg]chan 4 stop tone
18:20:40.859[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000923
18:20:40.869[app:dbg]vapi_proc_event: VAPI_CB
18:20:40.869[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000923 result 0x00000000
18:20:40.869[app:dbg]Conn 4: Stop tone - Successfull
18:20:40.869[app:dbg]Port 4: check vapi queue ('busy''stop_tone') at vapi_next_ops:2532
18:20:40.879[app:dbg]vapi: generic event, code 2 <Tone Generation completed>, conn 4
18:20:41.359[app:dbg]slic4. Event 1.
18:20:41.359[app:dbg]slic 4. On-hook event
18:20:41.359[app:dbg]Set port 4 led to state 'LED_OFF'
18:20:41.359[app:dbg]HIO: onhook TDM port '4', port enabled 1
18:20:41.359[app:dbg]SLIC 4 (1102): onhook state: busy
18:20:41.359[app:dbg]regex ID 4: dial reset
18:20:41.359[app:info]SLIC 4: from state 'busy' to state 'hangup'
18:20:41.359[app:dbg]CMD_STOP_TONE: port = 4
18:20:41.359[app:dbg]Port 4: check vapi queue ('free') at vapi_stop_tone_chan:1474
18:20:41.359[app:dbg]Chan 4: current state is CREATED
18:20:41.359[app:ERR]chan 4: no generated tones!
18:20:41.359[app:dbg]vapi_chan.c:1510: conn 4 peek cmd 'no event' from queue
18:20:41.359[app:dbg]Port 4: check vapi queue ('free') at __cmd_engine:320
18:20:41.359[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2532
18:20:41.359[app:dbg]SLIC 4: reset
18:20:41.359[app:dbg]dump_port_calls() SLIC 4:
18:20:41.359[app:dbg]Q:NONE
18:20:41.359[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:20:41.359[app:dbg]free_final_mx: final_mx was NULL for SLIC 4
18:20:41.359[app:dbg]CMD_DESTROY_CONN: port = 4
18:20:41.359[app:dbg]Port 4: check vapi queue ('free') at vapi_destroy_chan:890
18:20:41.359[app:dbg]Destroying connection 4...
18:20:41.359[app:dbg]Chan 4: current state is CREATED
18:20:41.359[app:dbg]Port 4: set vapi queue MSP to 'busy' with 'destroy' at vapi_destroy_chan:916
18:20:41.359[app:dbg]VQ Conn 4 = MSP :       'destroy' =
18:20:41.359[app:dbg]Chan 4: CREATED -> DESTROYING
18:20:41.359[app:dbg]CMD_DESTROY_IPONLY_CONN: port = 4
18:20:41.359[app:dbg]Port 4: check vapi queue ('busy''destroy') at vapi_destroy_chan:890
18:20:41.359[app:dbg]Clear vapi queue of Port 4/chan 12
18:20:41.359[app:dbg]Port 4 put cmd 'destroy',cur 'destroy' to queue at (vapi_destroy_chan:897)
18:20:41.359[app:dbg]VQ Conn 12 = MSP :       'destroy' =
18:20:41.359[app:dbg]VQ Conn 12 + 00  :       'destroy' (hold) + <-get_ptr
18:20:41.359[app:dbg]Port 4: user port 2, old state hangup, new state
18:20:41.359[app:dbg]Set port 4 led to state 'LED_OFF'
18:20:41.359[app:dbg]pbx -[msg_fxs_state]-> group
18:20:41.359[app:dbg]Delete all RX-TX medias from SLIC 4
18:20:41.359[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x0000014b
18:20:41.359[app:dbg]ITC: [msg_fxs_state] -> group
18:20:41.359[app:dbg]-----[GM] self_fxs_state()
18:20:41.359[app:dbg]Port 4: new state is hangup
18:20:41.369[app:dbg]Delete all RX-TX medias from SLIC 12
18:20:41.379[app:dbg]Delete all RX-TX medias from SLIC 4
18:20:41.379[app:dbg]dump_port_calls() SLIC 4:
18:20:41.379[app:dbg]Q:NONE
18:20:41.379[app:dbg]H:((nil),0x00000000,(nil),0) W:((nil),0x00000000,(nil)) N:((nil),0x00000000,(nil)) H2:((nil),0x00000000,(nil))
18:20:41.379[app:dbg]Set port 4 led to state 'LED_OFF'
18:20:41.389[app:dbg]vapi_proc_event: VAPI_CB
18:20:41.389[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x0000014b result 0x00000000
18:20:41.389[app:dbg]vapi_cb_req: 4 0 result 0x00000000 requid 0x00000103
18:20:41.399[app:dbg]vapi_proc_event: VAPI_CB
18:20:41.399[app:dbg]vapi_cb_chan: chan 4 reqest_id 0x00000103 result 0x00000000
18:20:41.399[app:dbg]Conn 4 destroyed
18:20:41.399[app:dbg]Chan 4: DESTROYING -> INITIAL
18:20:41.399[app:dbg]Port 4: check vapi queue ('busy''destroy') at vapi_next_ops:2532
18:20:41.399[app:dbg]Port 4 get cmd 'destroy' from queue at (vapi_next_ops:2551)
18:20:41.399[app:dbg]Port 4: check vapi queue ('free') at vapi_destroy_chan:890
18:20:41.399[app:dbg]Destroying connection 12...
18:20:41.399[app:dbg]Chan 12: current state is INITIAL
18:20:41.399[app:ERR]vapi_destroy_chan() chan 12: current state initial: duplicate destroying connection!
18:20:41.399[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2694
18:20:41.399[app:dbg]Port 4: check vapi queue ('free') at vapi_next_ops:2532
